1// Copyright (c) 2011 The Chromium Authors. All rights reserved.
2// Use of this source code is governed by a BSD-style license that can be
3// found in the LICENSE file.
4
5#include "tools/cygprofile/cygprofile.h"
6
7#include <fcntl.h>
8#include <pthread.h>
9#include <sys/stat.h>
10#include <sys/syscall.h>
11#include <sys/time.h>
12#include <sys/types.h>
13
14#include <cstdio>
15#include <fstream>
16#include <string>
17#include <vector>
18
19#include "base/bind.h"
20#include "base/containers/hash_tables.h"
21#include "base/files/scoped_file.h"
22#include "base/lazy_instance.h"
23#include "base/logging.h"
24#include "base/macros.h"
25#include "base/stl_util.h"
26#include "base/strings/string_number_conversions.h"
27#include "base/strings/string_piece.h"
28#include "base/strings/stringprintf.h"
29#include "base/synchronization/lock.h"
30
31namespace cygprofile {
32namespace {
33
34// Allow 8 MBytes of data for each thread log.
35const int kMaxBufferSize = 8 * 1024 * 1024 / sizeof(LogEntry);
36
37// Have the background internal thread do its flush every 15 sec.
38const int kFlushThreadIdleTimeSec = 15;
39
40const char kLogFileNamePrefix[] = "/data/local/tmp/chrome/cyglog/";
41
42// "cyglog.PID.LWP.PPID"
43const char kLogFilenameFormat[] = "%scyglog.%d.%d-%d";
44
45// Magic value of above to prevent instrumentation. Used when ThreadLog is being
46// constructed (to prevent reentering by malloc, for example) and by the flush
47// log thread (to prevent it from being logged0.
48ThreadLog* const kMagicBeingConstructed = reinterpret_cast<ThreadLog*>(1);
49
50// Per-thread pointer to the current log object.
51static __thread ThreadLog* g_tls_log = NULL;
52
53// Returns light-weight process ID. On Linux, this is a system-wide unique
54// thread id.
55pid_t GetTID() {
56  return syscall(__NR_gettid);
57}
58
59timespec GetCurrentTime() {
60  timespec timestamp;
61  clock_gettime(CLOCK_MONOTONIC, &timestamp);
62  return timestamp;
63}
64
65// Sleeps for |sec| seconds.
66void SleepSec(int sec) {
67  for (int secs_to_sleep = sec; secs_to_sleep != 0;)
68    secs_to_sleep = sleep(secs_to_sleep);
69}
70
71// Exposes the string header that will appear at the top of every trace file.
72// This string contains memory mapping information for the mapped
73// library/executable which is used offline during symbolization. Note that
74// this class is meant to be instantiated once per process and lazily (during
75// the first flush).
76struct ImmutableFileHeaderLine {
77  ImmutableFileHeaderLine() : value(MakeFileHeaderLine()) {}
78
79  const std::string value;
80
81 private:
82  // Returns whether the integer representation of the hexadecimal address
83  // stored in |line| at position |start_offset| was successfully stored in
84  // |result|.
85  static bool ParseAddress(const std::string& line,
86                           off_t start_offset,
87                           size_t length,
88                           uint64* result) {
89    if (start_offset >= line.length())
90      return false;
91
92    uint64 address;
93    const bool ret = HexStringToUInt64(
94        base::StringPiece(line.c_str() + start_offset, length), &address);
95    if (!ret)
96      return false;
97
98    *result = address;
99    return true;
100  }
101
102  // Parses /proc/self/maps and returns a two line string such as:
103  // 758c6000-79f4b000 r-xp 00000000 b3:17 309475 libchrome.2009.0.so
104  // secs    usecs   pid:threadid    func
105  static std::string MakeFileHeaderLine() {
106    std::ifstream mapsfile("/proc/self/maps");
107    CHECK(mapsfile.good());
108    std::string result;
109
110    for (std::string line; std::getline(mapsfile, line); ) {
111      if (line.find("r-xp") == std::string::npos)
112        continue;
113
114      const size_t address_length = line.find('-');
115      uint64 start_address = 0;
116      CHECK(ParseAddress(line, 0, address_length, &start_address));
117
118      uint64 end_address = 0;
119      CHECK(ParseAddress(line, address_length + 1, address_length,
120                         &end_address));
121
122      const uintptr_t current_func_addr = reinterpret_cast<uintptr_t>(
123          &MakeFileHeaderLine);
124      if (current_func_addr >= start_address &&
125          current_func_addr < end_address) {
126        result.swap(line);
127        break;
128      }
129    }
130    CHECK(!result.empty());
131    result.append("\nsecs\tusecs\tpid:threadid\tfunc\n");
132    return result;
133  }
134};
135
136base::LazyInstance<ThreadLogsManager>::Leaky g_logs_manager =
137    LAZY_INSTANCE_INITIALIZER;
138
139base::LazyInstance<ImmutableFileHeaderLine>::Leaky g_file_header_line =
140    LAZY_INSTANCE_INITIALIZER;
141
142}  // namespace
143
144// Custom thread implementation that joins on destruction. Note that
145// base::Thread has non-trivial dependencies on e.g. AtExitManager which makes
146// it hard to use it early.
147class Thread {
148 public:
149  Thread(const base::Closure& thread_callback)
150      : thread_callback_(thread_callback) {
151    CHECK_EQ(0, pthread_create(&handle_, NULL, &Thread::EntryPoint, this));
152  }
153
154  ~Thread() {
155    CHECK_EQ(0, pthread_join(handle_, NULL));
156  }
157
158 private:
159  static void* EntryPoint(void* data) {
160    // Disable logging on this thread. Although this routine is not instrumented
161    // (cygprofile.gyp provides that), the called routines are and thus will
162    // call instrumentation.
163    CHECK(g_tls_log == NULL);  // Must be 0 as this is a new thread.
164    g_tls_log = kMagicBeingConstructed;
165
166    Thread* const instance = reinterpret_cast<Thread*>(data);
167    instance->thread_callback_.Run();
168    return NULL;
169  }
170
171  const base::Closure thread_callback_;
172  pthread_t handle_;
173
174  DISALLOW_COPY_AND_ASSIGN(Thread);
175};
176
177// Single log entry recorded for each function call.
178LogEntry::LogEntry(const void* address)
179    : time(GetCurrentTime()),
180      pid(getpid()),
181      tid(GetTID()),
182      address(address) {
183}
184
185ThreadLog::ThreadLog()
186  : tid_(GetTID()),
187    in_use_(false),
188    flush_callback_(
189        base::Bind(&ThreadLog::FlushInternal, base::Unretained(this))) {
190}
191
192ThreadLog::ThreadLog(const FlushCallback& flush_callback)
193  : tid_(GetTID()),
194    in_use_(false),
195    flush_callback_(flush_callback) {
196}
197
198ThreadLog::~ThreadLog() {
199  g_tls_log = NULL;
200}
201
202void ThreadLog::AddEntry(void* address) {
203  if (in_use_)
204    return;
205  in_use_ = true;
206
207  CHECK_EQ(tid_, GetTID());
208  const std::pair<std::hash_set<void*>::iterator, bool> pair =
209      called_functions_.insert(address);
210  const bool did_insert = pair.second;
211
212  if (did_insert) {
213    base::AutoLock auto_lock(lock_);
214    entries_.push_back(LogEntry(address));
215    // Crash in a quickly understandable way instead of crashing (or maybe not
216    // though) due to OOM.
217    CHECK_LE(entries_.size(), kMaxBufferSize);
218  }
219
220  in_use_ = false;
221}
222
223void ThreadLog::TakeEntries(std::vector<LogEntry>* destination) {
224  base::AutoLock auto_lock(lock_);
225  destination->swap(entries_);
226  STLClearObject(&entries_);
227}
228
229void ThreadLog::Flush(std::vector<LogEntry>* entries) const {
230  flush_callback_.Run(entries);
231}
232
233void ThreadLog::FlushInternal(std::vector<LogEntry>* entries) const {
234  const std::string log_filename(
235      base::StringPrintf(
236          kLogFilenameFormat, kLogFileNamePrefix, getpid(), tid_, getppid()));
237  const base::ScopedFILE file(fopen(log_filename.c_str(), "a"));
238  CHECK(file.get());
239
240  const long offset = ftell(file.get());
241  if (offset == 0)
242    fprintf(file.get(), "%s", g_file_header_line.Get().value.c_str());
243
244  for (std::vector<LogEntry>::const_iterator it = entries->begin();
245       it != entries->end(); ++it) {
246    fprintf(file.get(), "%ld %ld\t%d:%ld\t%p\n", it->time.tv_sec,
247            it->time.tv_nsec / 1000, it->pid, it->tid, it->address);
248  }
249
250  STLClearObject(entries);
251}
252
253ThreadLogsManager::ThreadLogsManager()
254    : wait_callback_(base::Bind(&SleepSec, kFlushThreadIdleTimeSec)) {
255}
256
257ThreadLogsManager::ThreadLogsManager(const base::Closure& wait_callback,
258                                     const base::Closure& notify_callback)
259
260    : wait_callback_(wait_callback),
261      notify_callback_(notify_callback) {
262}
263
264ThreadLogsManager::~ThreadLogsManager() {
265  // Note that the internal thread does some work until it sees |flush_thread_|
266  // = NULL.
267  scoped_ptr<Thread> flush_thread;
268  {
269    base::AutoLock auto_lock(lock_);
270    flush_thread_.swap(flush_thread);
271  }
272  flush_thread.reset();  // Joins the flush thread.
273
274  STLDeleteContainerPointers(logs_.begin(), logs_.end());
275}
276
277void ThreadLogsManager::AddLog(scoped_ptr<ThreadLog> new_log) {
278  base::AutoLock auto_lock(lock_);
279
280  if (logs_.empty())
281    StartInternalFlushThread_Locked();
282
283  logs_.push_back(new_log.release());
284}
285
286void ThreadLogsManager::StartInternalFlushThread_Locked() {
287  lock_.AssertAcquired();
288  CHECK(!flush_thread_);
289  // Note that the |flush_thread_| joins at destruction which guarantees that it
290  // will never outlive |this|, i.e. it's safe not to use ref-counting.
291  flush_thread_.reset(
292      new Thread(base::Bind(&ThreadLogsManager::FlushAllLogsOnFlushThread,
293                            base::Unretained(this))));
294}
295
296// Type used below for flushing.
297struct LogData {
298  LogData(ThreadLog* thread_log) : thread_log(thread_log) {}
299
300  ThreadLog* const thread_log;
301  std::vector<LogEntry> entries;
302};
303
304void ThreadLogsManager::FlushAllLogsOnFlushThread() {
305  while (true) {
306    {
307      base::AutoLock auto_lock(lock_);
308      // The |flush_thread_| field is reset during destruction.
309      if (!flush_thread_)
310        return;
311    }
312    // Sleep for a few secs and then flush all thread's buffers. There is a
313    // danger that, when quitting Chrome, this thread may see unallocated data
314    // and segfault. We do not care because we need logs when Chrome is working.
315    wait_callback_.Run();
316
317    // Copy the ThreadLog pointers to avoid acquiring both the logs manager's
318    // lock and the one for individual thread logs.
319    std::vector<ThreadLog*> thread_logs_copy;
320    {
321      base::AutoLock auto_lock(lock_);
322      thread_logs_copy = logs_;
323    }
324
325    // Move the logs' data before flushing them so that the mutexes are not
326    // acquired for too long.
327    std::vector<LogData> logs;
328    for (std::vector<ThreadLog*>::const_iterator it =
329             thread_logs_copy.begin();
330         it != thread_logs_copy.end(); ++it) {
331      ThreadLog* const thread_log = *it;
332      LogData log_data(thread_log);
333      logs.push_back(log_data);
334      thread_log->TakeEntries(&logs.back().entries);
335    }
336
337    for (std::vector<LogData>::iterator it = logs.begin();
338         it != logs.end(); ++it) {
339      if (!it->entries.empty())
340        it->thread_log->Flush(&it->entries);
341    }
342
343    if (!notify_callback_.is_null())
344      notify_callback_.Run();
345  }
346}
347
348extern "C" {
349
350// The GCC compiler callbacks, called on every function invocation providing
351// addresses of caller and callee codes.
352void __cyg_profile_func_enter(void* this_fn, void* call_site)
353    __attribute__((no_instrument_function));
354void __cyg_profile_func_exit(void* this_fn, void* call_site)
355    __attribute__((no_instrument_function));
356
357void __cyg_profile_func_enter(void* this_fn, void* callee_unused) {
358  if (g_tls_log == NULL) {
359    g_tls_log = kMagicBeingConstructed;
360    ThreadLog* new_log = new ThreadLog();
361    CHECK(new_log);
362    g_logs_manager.Pointer()->AddLog(make_scoped_ptr(new_log));
363    g_tls_log = new_log;
364  }
365
366  if (g_tls_log != kMagicBeingConstructed)
367    g_tls_log->AddEntry(this_fn);
368}
369
370void __cyg_profile_func_exit(void* this_fn, void* call_site) {}
371
372}  // extern "C"
373}  // namespace cygprofile
374