tools/cygprofile/cygprofile.cc

   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
  31 namespace cygprofile {
  32 namespace {
  33
  34 // Allow 8 MBytes of data for each thread log.
  35 const int kMaxBufferSize = 8 * 1024 * 1024 / sizeof(LogEntry);
  36
  37 // Have the background internal thread do its flush every 15 sec.
  38 const int kFlushThreadIdleTimeSec = 15;
  39
  40 const char kLogFileNamePrefix[] = "/data/local/tmp/chrome/cyglog/";
  41
  42 // "cyglog.PID.LWP.PPID"
  43 const 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.
  48 ThreadLog* const kMagicBeingConstructed = reinterpret_cast<ThreadLog*>(1);
  49
  50 // Per-thread pointer to the current log object.
  51 static __thread ThreadLog* g_tls_log = NULL;
  52
  53 // Returns light-weight process ID. On Linux, this is a system-wide unique
  54 // thread id.
  55 pid_t GetTID() {
  56   return syscall(__NR_gettid);
  57 }
  58
  59 timespec GetCurrentTime() {
  60   timespec timestamp;
  61   clock_gettime(CLOCK_MONOTONIC, &timestamp);
  62   return timestamp;
  63 }
  64
  65 // Sleeps for |sec| seconds.
  66 void 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).
  76 struct 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
 136 base::LazyInstance<ThreadLogsManager>::Leaky g_logs_manager =
 137     LAZY_INSTANCE_INITIALIZER;
 138
 139 base::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.
 147 class 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.
 178 LogEntry::LogEntry(const void* address)
 179     : time(GetCurrentTime()),
 180       pid(getpid()),
 181       tid(GetTID()),
 182       address(address) {
 183 }
 184
 185 ThreadLog::ThreadLog()
 186   : tid_(GetTID()),
 187     in_use_(false),
 188     flush_callback_(
 189         base::Bind(&ThreadLog::FlushInternal, base::Unretained(this))) {
 190 }
 191
 192 ThreadLog::ThreadLog(const FlushCallback& flush_callback)
 193   : tid_(GetTID()),
 194     in_use_(false),
 195     flush_callback_(flush_callback) {
 196 }
 197
 198 ThreadLog::~ThreadLog() {
 199   g_tls_log = NULL;
 200 }
 201
 202 void ThreadLog::AddEntry(void* address) {
 203   if (in_use_)
 204     return;
 205   in_use_ = true;
 206
 207   CHECK_EQ(tid_, GetTID());
 208   const std::pair<base::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
 223 void ThreadLog::TakeEntries(std::vector<LogEntry>* destination) {
 224   base::AutoLock auto_lock(lock_);
 225   destination->swap(entries_);
 226   STLClearObject(&entries_);
 227 }
 228
 229 void ThreadLog::Flush(std::vector<LogEntry>* entries) const {
 230   flush_callback_.Run(entries);
 231 }
 232
 233 void 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
 253 ThreadLogsManager::ThreadLogsManager()
 254     : wait_callback_(base::Bind(&SleepSec, kFlushThreadIdleTimeSec)) {
 255 }
 256
 257 ThreadLogsManager::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
 264 ThreadLogsManager::~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
 277 void 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
 286 void 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.
 297 struct LogData {
 298   LogData(ThreadLog* thread_log) : thread_log(thread_log) {}
 299
 300   ThreadLog* const thread_log;
 301   std::vector<LogEntry> entries;
 302 };
 303
 304 void 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
 348 extern "C" {
 349
 350 // The GCC compiler callbacks, called on every function invocation providing
 351 // addresses of caller and callee codes.
 352 void __cyg_profile_func_enter(void* this_fn, void* call_site)
 353     __attribute__((no_instrument_function));
 354 void __cyg_profile_func_exit(void* this_fn, void* call_site)
 355     __attribute__((no_instrument_function));
 356
 357 void __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
 370 void __cyg_profile_func_exit(void* this_fn, void* call_site) {}
 371
 372 }  // extern "C"
 373 }  // namespace cygprofile