Refactor cygprofile.cc, drop support for non-Android and add unit tests.

This refactors cygprofile.cc by:
- Removing unnecessary uses of pthread_self().
- Splitting the CygTlsLog class into two pieces: ThreadLog and
  ThreadLogsManager.  ThreadLog is the per-thread trace log while
  ThreadLogsManager is the global instance that manages individual trace logs
  and handles flushing through its internal thread.
- Encapsulating more state (e.g. the vector of trace logs).
- Minimizing global state by removing the CygCommon class.
- Enforcing immutability in various places which allows more type-safety and
  less locking in particular.
- Sanitizing locking mechanisms: |ThreadLogsManager::lock_| and
  |ThreadLog::lock_| are now never acquired at the same time and critical
  sections are shortened to avoid subtle lock interactions.
- Flushing only from the background flush thread to mitigate the observer
  effect.

This also drops support for non-Android platforms since it was randomly
deadlocking at best. See the detailed comment at the top of cygprofile.h for
more information.

Additionally this introduces cygprofile.h which exposes the necessary bits for
the new unit tests added in cygprofile_unittest.cc.

BUG=372323
R=pasko@chromium.org

Review URL: https://codereview.chromium.org/296793004

git-svn-id: svn://svn.chromium.org/chrome/trunk/src@275045 0039d316-1c4b-4281-b951-d872f2087c98

4 files changed, 570 insertions, 312 deletions

diff --git a/tools/cygprofile/cygprofile.cc b/tools/cygprofile/cygprofile.cc
index 980fa9e..5d0e370 100644
--- a/tools/cygprofile/cygprofile.cc
+++ b/tools/cygprofile/cygprofile.cc
@@ -1,401 +1,373 @@
 // Copyright (c) 2011 The Chromium Authors. All rights reserved.
 // Use of this source code is governed by a BSD-style license that can be
 // found in the LICENSE file.
-//
-// Tool to log the execution of the process (Chrome). Writes logs containing
-// time and address of the callback being called for the first time.
-//
-// To speed up the logging, buffering logs is implemented. Every thread have its
-// own buffer and log file so the contention between threads is minimal. As a
-// side-effect, functions called might be mentioned in many thread logs.
-//
-// Special thread is created in the process to periodically flushes logs for all
-// threads for the case the thread has stopped before flushing its logs.
-//
-// Use this profiler with use_allocator!="none".
-//
-// Note for the ChromeOS Chrome. Remove renderer process from the sandbox (add
-// --no-sandbox option to running Chrome in /sbin/session_manager_setup.sh).
-// Otherwise renderer will not be able to write logs (and will assert on that).
-//
-// Also note that the instrumentation code is self-activated. It begins to
-// record the log data when it is called first, including the run-time startup.
-// Have it in mind when modifying it, in particular do not use global objects
-// with constructors as they are called during startup (too late for us).
+
+#include "tools/cygprofile/cygprofile.h"
 
 #include <fcntl.h>
-#include <fstream>
 #include <pthread.h>
-#include <stdarg.h>
-#include <string>
 #include <sys/stat.h>
 #include <sys/syscall.h>
 #include <sys/time.h>
 #include <sys/types.h>
+
+#include <cstdio>
+#include <fstream>
+#include <string>
 #include <vector>
 
+#include "base/bind.h"
 #include "base/containers/hash_tables.h"
+#include "base/files/scoped_file.h"
 #include "base/lazy_instance.h"
 #include "base/logging.h"
-#include "base/memory/singleton.h"
+#include "base/macros.h"
+#include "base/stl_util.h"
+#include "base/strings/string_number_conversions.h"
+#include "base/strings/string_piece.h"
+#include "base/strings/stringprintf.h"
 #include "base/synchronization/lock.h"
 
 namespace cygprofile {
+namespace {
 
-extern "C" {
+// Allow 8 MBytes of data for each thread log.
+const int kMaxBufferSize = 8 * 1024 * 1024 / sizeof(LogEntry);
 
-// Note that these are linked internally by the compiler. Don't call
-// them directly!
-void __cyg_profile_func_enter(void* this_fn, void* call_site)
-    __attribute__((no_instrument_function));
-void __cyg_profile_func_exit(void* this_fn, void* call_site)
-    __attribute__((no_instrument_function));
+// Have the background internal thread do its flush every 15 sec.
+const int kFlushThreadIdleTimeSec = 15;
 
-}
+const char kLogFileNamePrefix[] = "/data/local/tmp/chrome/cyglog/";
 
-// Single log entry layout.
-struct CygLogEntry {
-  time_t seconds;
-  long int usec;
-  pid_t pid;
-  pthread_t tid;
-  const void* this_fn;
-  CygLogEntry(time_t seconds, long int usec,
-              pid_t pid, pthread_t tid, const void* this_fn)
-      : seconds(seconds), usec(usec),
-        pid(pid), tid(tid), this_fn(this_fn) {}
-};
+// "cyglog.PID.LWP.PPID"
+const char kLogFilenameFormat[] = "%scyglog.%d.%d-%d";
 
-// Common data for the process. Singleton.
-class CygCommon {
- public:
-  static CygCommon* GetInstance();
-  std::string header() const { return header_line_; }
- private:
-  CygCommon();
-  std::string header_line_;
-  friend struct DefaultSingletonTraits<CygCommon>;
+// Magic value of above to prevent instrumentation. Used when ThreadLog is being
+// constructed (to prevent reentering by malloc, for example) and by the flush
+// log thread (to prevent it from being logged0.
+ThreadLog* const kMagicBeingConstructed = reinterpret_cast<ThreadLog*>(1);
 
-  DISALLOW_COPY_AND_ASSIGN(CygCommon);
-};
+// Per-thread pointer to the current log object.
+static __thread ThreadLog* g_tls_log = NULL;
 
-// Returns light-weight process ID.  On linux, this is a system-wide
-// unique thread id.
-static pid_t GetLwp() {
+// Returns light-weight process ID. On Linux, this is a system-wide unique
+// thread id.
+pid_t GetTID() {
   return syscall(__NR_gettid);
 }
 
-// A per-thread structure representing the log itself.
-class CygTlsLog {
- public:
-  CygTlsLog()
-      : in_use_(false), lwp_(GetLwp()), pthread_self_(pthread_self()) { }
+timespec GetCurrentTime() {
+  timespec timestamp;
+  clock_gettime(CLOCK_MONOTONIC, &timestamp);
+  return timestamp;
+}
 
-  // Enter a log entity.
-  void LogEnter(void* this_fn);
+// Sleeps for |sec| seconds.
+void SleepSec(int sec) {
+  for (int secs_to_sleep = sec; secs_to_sleep != 0;)
+    secs_to_sleep = sleep(secs_to_sleep);
+}
 
-  // Add newly created CygTlsLog object to the list of all such objects.
-  // Needed for the timer callback: it will enumerate each object and flush.
-  static void AddNewLog(CygTlsLog* newlog);
+// Exposes the string header that will appear at the top of every trace file.
+// This string contains memory mapping information for the mapped
+// library/executable which is used offline during symbolization. Note that
+// this class is meant to be instantiated once per process and lazily (during
+// the first flush).
+struct ImmutableFileHeaderLine {
+  ImmutableFileHeaderLine() : value(MakeFileHeaderLine()) {}
 
-  // Starts a thread in this process that periodically flushes all the threads.
-  // Must be called once per process.
-  static void StartFlushLogThread();
+  const std::string value;
 
  private:
-  static const int kBufMaxSize;
-  static const char kLogFilenameFmt[];
-  static const char kLogFileNamePrefix[];
-
-  // Flush the log to file. Create file if needed.
-  // Must be called with locked log_mutex_.
-  void FlushLog();
+  // Returns whether the integer representation of the hexadecimal address
+  // stored in |line| at position |start_offset| was successfully stored in
+  // |result|.
+  static bool ParseAddress(const std::string& line,
+                           off_t start_offset,
+                           size_t length,
+                           uint64* result) {
+    if (start_offset >= line.length())
+      return false;
+
+    uint64 address;
+    const bool ret = HexStringToUInt64(
+        base::StringPiece(line.c_str() + start_offset, length), &address);
+    if (!ret)
+      return false;
+
+    *result = address;
+    return true;
+  }
 
-  // Fork hooks. Needed to keep data in consistent state during fork().
-  static void AtForkPrepare();
-  static void AtForkParent();
-  static void AtForkChild();
+  // Parses /proc/self/maps and returns a two line string such as:
+  // 758c6000-79f4b000 r-xp 00000000 b3:17 309475 libchrome.2009.0.so
+  // secs    usecs   pid:threadid    func
+  static std::string MakeFileHeaderLine() {
+    std::ifstream mapsfile("/proc/self/maps");
+    CHECK(mapsfile.good());
+    std::string result;
+
+    for (std::string line; std::getline(mapsfile, line); ) {
+      if (line.find("r-xp") == std::string::npos)
+        continue;
+
+      const size_t address_length = line.find('-');
+      uint64 start_address = 0;
+      CHECK(ParseAddress(line, 0, address_length, &start_address));
+
+      uint64 end_address = 0;
+      CHECK(ParseAddress(line, address_length + 1, address_length,
+                         &end_address));
+
+      const uintptr_t current_func_addr = reinterpret_cast<uintptr_t>(
+          &MakeFileHeaderLine);
+      if (current_func_addr >= start_address &&
+          current_func_addr < end_address) {
+        result.swap(line);
+        break;
+      }
+    }
+    CHECK(!result.empty());
+    result.append("\nsecs\tusecs\tpid:threadid\tfunc\n");
+    return result;
+  }
+};
 
-  // Thread callback to flush all logs periodically.
-  static void* FlushLogThread(void*);
+base::LazyInstance<ThreadLogsManager>::Leaky g_logs_manager =
+    LAZY_INSTANCE_INITIALIZER;
 
-  std::string log_filename_;
-  std::vector<CygLogEntry> buf_;
+base::LazyInstance<ImmutableFileHeaderLine>::Leaky g_file_header_line =
+    LAZY_INSTANCE_INITIALIZER;
 
-  // A lock that guards buf_ usage between per-thread instrumentation
-  // routine and timer flush callback. So the contention could happen
-  // only during the flush, every 30 secs.
-  base::Lock log_mutex_;
+}  // namespace
 
-  // Current thread is inside the instrumentation routine.
-  bool in_use_;
+// Custom thread implementation that joins on destruction. Note that
+// base::Thread has non-trivial dependencies on e.g. AtExitManager which makes
+// it hard to use it early.
+class Thread {
+ public:
+  Thread(const base::Closure& thread_callback)
+      : thread_callback_(thread_callback) {
+    CHECK_EQ(0, pthread_create(&handle_, NULL, &Thread::EntryPoint, this));
+  }
 
-  // Keeps track of all functions that have been logged on this thread
-  // so we do not record dublicates.
-  std::hash_set<void*> functions_called_;
+  ~Thread() {
+    CHECK_EQ(0, pthread_join(handle_, NULL));
+  }
 
-  // Thread identifier as Linux kernel shows it. For debugging purposes.
-  // LWP (light-weight process) is a unique ID of the thread in the system,
-  // unlike pthread_self() which is the same for fork()-ed threads.
-  pid_t lwp_;
-  pthread_t pthread_self_;
+ private:
+  static void* EntryPoint(void* data) {
+    // Disable logging on this thread. Although this routine is not instrumented
+    // (cygprofile.gyp provides that), the called routines are and thus will
+    // call instrumentation.
+    CHECK(g_tls_log == NULL);  // Must be 0 as this is a new thread.
+    g_tls_log = kMagicBeingConstructed;
+
+    Thread* const instance = reinterpret_cast<Thread*>(data);
+    instance->thread_callback_.Run();
+    return NULL;
+  }
 
-  DISALLOW_COPY_AND_ASSIGN(CygTlsLog);
-};
+  const base::Closure thread_callback_;
+  pthread_t handle_;
 
-// Storage for logs for all threads in the process.
-// Using std::list may be better, but it fails when used before main().
-struct AllLogs {
-  std::vector<CygTlsLog*> logs;
-  base::Lock mutex;
+  DISALLOW_COPY_AND_ASSIGN(Thread);
 };
 
-base::LazyInstance<AllLogs>::Leaky all_logs_ = LAZY_INSTANCE_INITIALIZER;
-
-// Per-thread pointer to the current log object.
-static __thread CygTlsLog* tls_current_log = NULL;
-
-// Magic value of above to prevent the instrumentation. Used when CygTlsLog is
-// being constructed (to prevent reentering by malloc, for example) and by
-// the FlushLogThread (to prevent it being logged - see comment in its code).
-CygTlsLog* const kMagicBeingConstructed = reinterpret_cast<CygTlsLog*>(1);
-
-// Number of entries in the per-thread log buffer before we flush.
-// Note, that we also flush by timer so not all thread logs may grow up to this.
-const int CygTlsLog::kBufMaxSize = 3000;
-
-#if defined(OS_ANDROID)
-const char CygTlsLog::kLogFileNamePrefix[] =
-    "/data/local/tmp/chrome/cyglog/";
-#else
-const char CygTlsLog::kLogFileNamePrefix[] = "/var/log/chrome/";
-#endif
+// Single log entry recorded for each function call.
+LogEntry::LogEntry(const void* address)
+    : time(GetCurrentTime()),
+      pid(getpid()),
+      tid(GetTID()),
+      address(address) {
+}
 
-// "cyglog.PID.LWP.pthread_self.PPID"
-const char CygTlsLog::kLogFilenameFmt[] = "%scyglog.%d.%d.%ld-%d";
+ThreadLog::ThreadLog()
+  : tid_(GetTID()),
+    in_use_(false),
+    flush_callback_(
+        base::Bind(&ThreadLog::FlushInternal, base::Unretained(this))) {
+}
 
-CygCommon* CygCommon::GetInstance() {
-  return Singleton<CygCommon>::get();
+ThreadLog::ThreadLog(const FlushCallback& flush_callback)
+  : tid_(GetTID()),
+    in_use_(false),
+    flush_callback_(flush_callback) {
 }
 
-CygCommon::CygCommon() {
-  // Determine our module addresses.
-  std::ifstream mapsfile("/proc/self/maps");
-  CHECK(mapsfile.good());
-  static const int kMaxLineSize = 512;
-  char line[kMaxLineSize];
-  void (*this_fn)(void) =
-      reinterpret_cast<void(*)()>(__cyg_profile_func_enter);
-  while (mapsfile.getline(line, kMaxLineSize)) {
-    const std::string str_line = line;
-    size_t permindex = str_line.find("r-xp");
-    if (permindex != std::string::npos) {
-      int dashindex = str_line.find("-");
-      int spaceindex = str_line.find(" ");
-      char* p;
-      void* start = reinterpret_cast<void*>
-          (strtol((str_line.substr(0, dashindex)).c_str(),
-                  &p, 16));
-      CHECK(*p == 0);  // Could not determine start address.
-      void* end = reinterpret_cast<void*>
-          (strtol((str_line.substr(dashindex + 1,
-                                   spaceindex - dashindex - 1)).c_str(),
-                  &p, 16));
-      CHECK(*p == 0);  // Could not determine end address.
-
-      if (this_fn >= start && this_fn < end)
-        header_line_ = str_line;
-    }
-  }
-  mapsfile.close();
-  header_line_.append("\nsecs\tusecs\tpid:threadid\tfunc\n");
+ThreadLog::~ThreadLog() {
+  g_tls_log = NULL;
 }
 
-void CygTlsLog::LogEnter(void* this_fn) {
+void ThreadLog::AddEntry(void* address) {
   if (in_use_)
     return;
   in_use_ = true;
 
-  if (functions_called_.find(this_fn) ==
-      functions_called_.end()) {
-    functions_called_.insert(this_fn);
-    base::AutoLock lock(log_mutex_);
-    if (buf_.capacity() < kBufMaxSize)
-      buf_.reserve(kBufMaxSize);
-    struct timespec timestamp;
-    clock_gettime(CLOCK_MONOTONIC, &timestamp);
-    buf_.push_back(CygLogEntry(timestamp.tv_sec, timestamp.tv_nsec / 1000,
-                               getpid(), pthread_self(), this_fn));
-    if (buf_.size() == kBufMaxSize) {
-      FlushLog();
-    }
+  CHECK_EQ(tid_, GetTID());
+  const std::pair<std::hash_set<void*>::iterator, bool> pair =
+      called_functions_.insert(address);
+  const bool did_insert = pair.second;
+
+  if (did_insert) {
+    base::AutoLock auto_lock(lock_);
+    entries_.push_back(LogEntry(address));
+    // Crash in a quickly understandable way instead of crashing (or maybe not
+    // though) due to OOM.
+    CHECK_LE(entries_.size(), kMaxBufferSize);
   }
 
   in_use_ = false;
 }
 
-void CygTlsLog::AtForkPrepare() {
-  CHECK(tls_current_log);
-  CHECK(tls_current_log->lwp_ == GetLwp());
-  CHECK(tls_current_log->pthread_self_ == pthread_self());
-  all_logs_.Get().mutex.Acquire();
+void ThreadLog::TakeEntries(std::vector<LogEntry>* destination) {
+  base::AutoLock auto_lock(lock_);
+  destination->swap(entries_);
+  STLClearObject(&entries_);
 }
 
-void CygTlsLog::AtForkParent() {
-  CHECK(tls_current_log);
-  CHECK(tls_current_log->lwp_ == GetLwp());
-  CHECK(tls_current_log->pthread_self_ == pthread_self());
-  all_logs_.Get().mutex.Release();
+void ThreadLog::Flush(std::vector<LogEntry>* entries) const {
+  flush_callback_.Run(entries);
 }
 
-void CygTlsLog::AtForkChild() {
-  CHECK(tls_current_log);
+void ThreadLog::FlushInternal(std::vector<LogEntry>* entries) const {
+  const std::string log_filename(
+      base::StringPrintf(
+          kLogFilenameFormat, kLogFileNamePrefix, getpid(), tid_, getppid()));
+  const base::ScopedFILE file(fopen(log_filename.c_str(), "a"));
+  CHECK(file.get());
+
+  const long offset = ftell(file.get());
+  if (offset == 0)
+    fprintf(file.get(), "%s", g_file_header_line.Get().value.c_str());
+
+  for (std::vector<LogEntry>::const_iterator it = entries->begin();
+       it != entries->end(); ++it) {
+    fprintf(file.get(), "%ld %ld\t%d:%ld\t%p\n", it->time.tv_sec,
+            it->time.tv_nsec / 1000, it->pid, it->tid, it->address);
+  }
 
-  // Update the IDs of this new thread of the new process.
-  // Note that the process may (and Chrome main process forks zygote this way)
-  // call exec(self) after we return (to launch new shiny self). If done like
-  // that, PID and LWP will remain the same, but pthread_self() changes.
-  pid_t lwp = GetLwp();
-  CHECK(tls_current_log->lwp_ != lwp);  // LWP is system-wide unique thread ID.
-  tls_current_log->lwp_ = lwp;
+  STLClearObject(entries);
+}
 
-  CHECK(tls_current_log->pthread_self_ == pthread_self());
+ThreadLogsManager::ThreadLogsManager()
+    : wait_callback_(base::Bind(&SleepSec, kFlushThreadIdleTimeSec)) {
+}
 
-  // Leave the only current thread tls object because fork() clones only the
-  // current thread (the one that called fork) to the child process.
-  AllLogs& all_logs = all_logs_.Get();
-  all_logs.logs.clear();
-  all_logs.logs.push_back(tls_current_log);
-  CHECK(all_logs.logs.size() == 1);
+ThreadLogsManager::ThreadLogsManager(const base::Closure& wait_callback,
+                                     const base::Closure& notify_callback)
 
-  // Clear log filename so it will be re-calculated with the new PIDs.
-  tls_current_log->log_filename_.clear();
+    : wait_callback_(wait_callback),
+      notify_callback_(notify_callback) {
+}
 
-  // Create the thread that will periodically flush all logs for this process.
-  StartFlushLogThread();
+ThreadLogsManager::~ThreadLogsManager() {
+  // Note that the internal thread does some work until it sees |flush_thread_|
+  // = NULL.
+  scoped_ptr<Thread> flush_thread;
+  {
+    base::AutoLock auto_lock(lock_);
+    flush_thread_.swap(flush_thread);
+  }
+  flush_thread.reset();  // Joins the flush thread.
 
-  // We do not update log header line (CygCommon data) as it will be the same
-  // because the new process is just a forked copy.
-  all_logs.mutex.Release();
+  STLDeleteContainerPointers(logs_.begin(), logs_.end());
 }
 
-void CygTlsLog::StartFlushLogThread() {
-  pthread_t tid;
-  CHECK(!pthread_create(&tid, NULL, &CygTlsLog::FlushLogThread, NULL));
+void ThreadLogsManager::AddLog(scoped_ptr<ThreadLog> new_log) {
+  base::AutoLock auto_lock(lock_);
+
+  if (logs_.empty())
+    StartInternalFlushThread_Locked();
+
+  logs_.push_back(new_log.release());
 }
 
-void CygTlsLog::AddNewLog(CygTlsLog* newlog) {
-  CHECK(tls_current_log == kMagicBeingConstructed);
-  AllLogs& all_logs = all_logs_.Get();
-  base::AutoLock lock(all_logs.mutex);
-  if (all_logs.logs.empty()) {
-
-    // An Android app never fork, it always starts with a pre-defined number of
-    // process descibed by the android manifest file. In fact, there is not
-    // support for pthread_atfork at the android system libraries.  All chrome
-    // for android processes will start as independent processs and each one
-    // will generate its own logs that will later have to be merged as usual.
-#if !defined(OS_ANDROID)
-    CHECK(!pthread_atfork(CygTlsLog::AtForkPrepare,
-                          CygTlsLog::AtForkParent,
-                          CygTlsLog::AtForkChild));
-#endif
-
-    // The very first process starts its flush thread here. Forked processes
-    // will do it in AtForkChild().
-    StartFlushLogThread();
-  }
-  all_logs.logs.push_back(newlog);
+void ThreadLogsManager::StartInternalFlushThread_Locked() {
+  lock_.AssertAcquired();
+  CHECK(!flush_thread_);
+  // Note that the |flush_thread_| joins at destruction which guarantees that it
+  // will never outlive |this|, i.e. it's safe not to use ref-counting.
+  flush_thread_.reset(
+      new Thread(base::Bind(&ThreadLogsManager::FlushAllLogsOnFlushThread,
+                            base::Unretained(this))));
 }
 
-// Printf-style routine to write to open file.
-static void WriteLogLine(int fd, const char* fmt, ...) {
-  va_list arg_ptr;
-  va_start(arg_ptr, fmt);
-  char msg[160];
-  int len = vsnprintf(msg, sizeof(msg), fmt, arg_ptr);
-  int rc = write(fd, msg, (len > sizeof(msg))? sizeof(msg): len);
-  va_end(arg_ptr);
+// Type used below for flushing.
+struct LogData {
+  LogData(ThreadLog* thread_log) : thread_log(thread_log) {}
+
+  ThreadLog* const thread_log;
+  std::vector<LogEntry> entries;
 };
 
-void CygTlsLog::FlushLog() {
-  bool first_log_write = false;
-  if (log_filename_.empty()) {
-    first_log_write = true;
-    char buf[80];
-    snprintf(buf, sizeof(buf), kLogFilenameFmt,
-             kLogFileNamePrefix, getpid(), lwp_, pthread_self_, getppid());
-    log_filename_ = buf;
-    unlink(log_filename_.c_str());
-  }
+void ThreadLogsManager::FlushAllLogsOnFlushThread() {
+  while (true) {
+    {
+      base::AutoLock auto_lock(lock_);
+      // The |flush_thread_| field is reset during destruction.
+      if (!flush_thread_)
+        return;
+    }
+    // Sleep for a few secs and then flush all thread's buffers. There is a
+    // danger that, when quitting Chrome, this thread may see unallocated data
+    // and segfault. We do not care because we need logs when Chrome is working.
+    wait_callback_.Run();
+
+    // Copy the ThreadLog pointers to avoid acquiring both the logs manager's
+    // lock and the one for individual thread logs.
+    std::vector<ThreadLog*> thread_logs_copy;
+    {
+      base::AutoLock auto_lock(lock_);
+      thread_logs_copy = logs_;
+    }
 
-  int file = open(log_filename_.c_str(), O_CREAT | O_WRONLY | O_APPEND, 00600);
-  CHECK(file != -1);
+    // Move the logs' data before flushing them so that the mutexes are not
+    // acquired for too long.
+    std::vector<LogData> logs;
+    for (std::vector<ThreadLog*>::const_iterator it =
+             thread_logs_copy.begin();
+         it != thread_logs_copy.end(); ++it) {
+      ThreadLog* const thread_log = *it;
+      LogData log_data(thread_log);
+      logs.push_back(log_data);
+      thread_log->TakeEntries(&logs.back().entries);
+    }
 
-  if (first_log_write)
-    WriteLogLine(file, "%s", CygCommon::GetInstance()->header().c_str());
+    for (std::vector<LogData>::iterator it = logs.begin();
+         it != logs.end(); ++it) {
+      if (!it->entries.empty())
+        it->thread_log->Flush(&it->entries);
+    }
 
-  for (int i = 0; i != buf_.size(); ++i) {
-    const CygLogEntry& p = buf_[i];
-    WriteLogLine(file, "%ld %ld\t%d:%ld\t%p\n",
-                 p.seconds, p.usec, p.pid, p.tid, p.this_fn);
+    if (!notify_callback_.is_null())
+      notify_callback_.Run();
   }
-
-  close(file);
-  buf_.clear();
 }
 
-void* CygTlsLog::FlushLogThread(void*) {
-  // Disable logging this thread.  Although this routine is not instrumented
-  // (cygprofile.gyp provides that), the called routines are and thus will
-  // call instrumentation.
-  CHECK(tls_current_log == NULL);  // Must be 0 as this is a new thread.
-  tls_current_log = kMagicBeingConstructed;
-
-  // Run this loop infinitely: sleep 30 secs and the flush all thread's
-  // buffers.  There is a danger that, when quitting Chrome, this thread may
-  // see unallocated data and segfault. We do not care because we need logs
-  // when Chrome is working.
-  while (true) {
-    for(int secs_to_sleep = 30; secs_to_sleep != 0;)
-      secs_to_sleep = sleep(secs_to_sleep);
-
-    AllLogs& all_logs = all_logs_.Get();
-    base::AutoLock lock(all_logs.mutex);
-    for (int i = 0; i != all_logs.logs.size(); ++i) {
-      CygTlsLog* current_log = all_logs.logs[i];
-      base::AutoLock current_lock(current_log->log_mutex_);
-      if (current_log->buf_.size()) {
-        current_log->FlushLog();
-      } else {
-        // The thread's log is still empty. Probably the thread finished prior
-        // to previous timer fired - deallocate its buffer. Even if the thread
-        // ever resumes, it will allocate its buffer again in
-        // std::vector::push_back().
-        current_log->buf_.clear();
-      }
-    }
-  }
-}
+extern "C" {
 
-// Gcc Compiler callback, called on every function invocation providing
+// The GCC compiler callbacks, called on every function invocation providing
 // addresses of caller and callee codes.
+void __cyg_profile_func_enter(void* this_fn, void* call_site)
+    __attribute__((no_instrument_function));
+void __cyg_profile_func_exit(void* this_fn, void* call_site)
+    __attribute__((no_instrument_function));
+
 void __cyg_profile_func_enter(void* this_fn, void* callee_unused) {
-  if (tls_current_log == NULL) {
-    tls_current_log = kMagicBeingConstructed;
-    CygTlsLog* newlog = new CygTlsLog;
-    CHECK(newlog);
-    CygTlsLog::AddNewLog(newlog);
-    tls_current_log = newlog;
+  if (g_tls_log == NULL) {
+    g_tls_log = kMagicBeingConstructed;
+    ThreadLog* new_log = new ThreadLog();
+    CHECK(new_log);
+    g_logs_manager.Pointer()->AddLog(make_scoped_ptr(new_log));
+    g_tls_log = new_log;
   }
-  if (tls_current_log != kMagicBeingConstructed) {
-    tls_current_log->LogEnter(this_fn);
-  }
-}
 
-// Gcc Compiler callback, called after every function invocation providing
-// addresses of caller and callee codes.
-void __cyg_profile_func_exit(void* this_fn, void* call_site) {
+  if (g_tls_log != kMagicBeingConstructed)
+    g_tls_log->AddEntry(this_fn);
 }
 
+void __cyg_profile_func_exit(void* this_fn, void* call_site) {}
+
+}  // extern "C"
 }  // namespace cygprofile
diff --git a/tools/cygprofile/cygprofile.gyp b/tools/cygprofile/cygprofile.gyp
index 1e7c751..910ef54 100644
--- a/tools/cygprofile/cygprofile.gyp
+++ b/tools/cygprofile/cygprofile.gyp
@@ -3,8 +3,6 @@
 # found in the LICENSE file.
 
 {
-  'variables': {
-  },
   'targets': [
     {
       'target_name': 'cygprofile',
@@ -12,8 +10,29 @@
       'include_dirs': [ '../..', ],
       'sources': [
         'cygprofile.cc',
+        'cygprofile.h',
       ],
       'cflags!': [ '-finstrument-functions' ],
+      'dependencies': [
+        # This adds uninstrumented symbols to the static library from base.
+        # These symbols are likely *not* to be used because there are many
+        # other duplicates in other objects/libraries.
+        '../../base/base.gyp:base',
+      ],
+    },
+    {
+      'target_name': 'cygprofile_unittests',
+      'type': 'executable',
+      'include_dirs': [ '../..', ],
+      'sources': [
+        'cygprofile_unittest.cc',
+      ],
+      'cflags!': [ '-finstrument-functions' ],
+      'dependencies': [
+        'cygprofile',
+        '../../base/base.gyp:base',
+        '../../testing/gtest.gyp:gtest',
+      ],
     },
   ],
 }
diff --git a/tools/cygprofile/cygprofile.h b/tools/cygprofile/cygprofile.h
new file mode 100644
index 0000000..eeb3ffb
--- /dev/null
+++ b/tools/cygprofile/cygprofile.h
@@ -0,0 +1,166 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+//
+// Tool to log the execution of the process (Chrome). Writes logs containing
+// time and address of the callback being called for the first time.
+//
+// For performance reasons logs are buffered. Every thread has its own buffer
+// and log file so the contention between threads is minimal. As a side-effect,
+// functions called might be mentioned in many thread logs.
+//
+// A special thread is created in the process to periodically flush logs for all
+// threads in case the thread had stopped before flushing its logs.
+//
+// Also note that the instrumentation code is self-activated. It begins to
+// record the log data when it is called first, including the run-time startup.
+// Have it in mind when modifying it, in particular do not use global objects
+// with constructors as they are called during startup (too late for us).
+
+#ifndef TOOLS_CYGPROFILE_CYGPROFILE_H_
+#define TOOLS_CYGPROFILE_CYGPROFILE_H_
+
+#include <vector>
+
+#include <sys/time.h>
+#include <sys/types.h>
+
+#include "base/callback.h"
+#include "base/containers/hash_tables.h"
+#include "base/macros.h"
+#include "base/memory/scoped_ptr.h"
+#include "base/synchronization/lock.h"
+#include "build/build_config.h"
+
+#if !defined(OS_ANDROID)
+// This is only supported on Android thanks to the fact that on Android
+// processes (other than the system's zygote) don't fork.
+//
+// To make cygprofile truly work (i.e. without any deadlock) on Chrome
+// platforms that use fork(), cygprofile.cc should be written in a way that
+// guarantees that:
+// - No lock is acquired by a foreign thread during fork(). In particular this
+// means that cygprofile.cc should not perform any heap allocation (since heap
+// allocators, including TCMalloc generally use locks).
+// - Only cygprofile.cc uses pthread_atfork() in the whole process. Unlike POSIX
+// signals, pthread_atfork() doesn't provide a way to install multiple handlers.
+// Calling pthread_atfork() in cygprofile.cc would override any handler that
+// could have been installed previously.
+//
+// Chrome happens to violate the first requirement at least once by having its
+// process launcher thread fork. However the child process in that case, when
+// it's not instrumented with cygprofile, directly calls exec(). This is safe
+// since the child process doesn't try to release a lock acquired by another
+// thread in the parent process which would lead to a deadlock. This problem was
+// actually observed by trying to port the current version of cygprofile.cc to
+// Linux.
+#error This is only supported on Android.
+#endif
+
+// The following is only exposed for testing.
+namespace cygprofile {
+
+class Thread;
+
+// Single log entry recorded for each function call.
+struct LogEntry {
+  LogEntry(const void* address);
+
+  const timespec time;
+  const pid_t pid;
+  const pid_t tid;
+  const void* const address;
+};
+
+// Per-thread function calls log.
+class ThreadLog {
+ public:
+  // Callback invoked for flushing that can be provided for testing.
+  typedef base::Callback<void (std::vector<LogEntry>*)> FlushCallback;
+
+  ThreadLog();
+
+  // Used for testing.
+  ThreadLog(const FlushCallback& flush_callback);
+
+  ~ThreadLog();
+
+  // Must only be called from the thread this ThreadLog instance is watching.
+  void AddEntry(void* address);
+
+  // Can be called from any thread.
+  void TakeEntries(std::vector<LogEntry>* output);
+
+  // Flushes the provided vector of entries to a file and clears it. Note that
+  // this can be called from any thread.
+  void Flush(std::vector<LogEntry>* entries) const;
+
+ private:
+  // Default implementation (that can be overridden for testing) of the method
+  // above.
+  void FlushInternal(std::vector<LogEntry>* entries) const;
+
+  // Thread identifier as Linux kernel shows it.  LWP (light-weight process) is
+  // a unique ID of the thread in the system, unlike pthread_self() which is the
+  // same for fork()-ed threads.
+  const pid_t tid_;
+
+  // Current thread is inside the instrumentation routine.
+  bool in_use_;
+
+  // Callback used to flush entries.
+  const FlushCallback flush_callback_;
+
+  // Keeps track of all functions that have been logged on this thread so we do
+  // not record duplicates.
+  std::hash_set<void*> called_functions_;
+
+  // A lock that guards |entries_| usage between per-thread instrumentation
+  // routine and timer flush callback. So the contention could happen only
+  // during the flush, every 15 secs.
+  base::Lock lock_;
+
+  std::vector<LogEntry> entries_;
+
+  DISALLOW_COPY_AND_ASSIGN(ThreadLog);
+};
+
+// Manages a list of per-thread logs.
+class ThreadLogsManager {
+ public:
+  ThreadLogsManager();
+
+  // Used for testing. The provided callbacks are used for testing to
+  // synchronize the internal thread with the unit test running on the main
+  // thread.
+  ThreadLogsManager(const base::Closure& wait_callback,
+                    const base::Closure& notify_callback);
+
+  ~ThreadLogsManager();
+
+  // Can be called from any thread.
+  void AddLog(scoped_ptr<ThreadLog> new_log);
+
+ private:
+  void StartInternalFlushThread_Locked();
+
+  // Flush thread's entry point.
+  void FlushAllLogsOnFlushThread();
+
+  // Used to make the internal thread sleep before each flush iteration.
+  const base::Closure wait_callback_;
+  // Used to trigger a notification when a flush happened on the internal
+  // thread.
+  const base::Closure notify_callback_;
+
+  // Protects the state below.
+  base::Lock lock_;
+  scoped_ptr<Thread> flush_thread_;
+  std::vector<ThreadLog*> logs_;
+
+  DISALLOW_COPY_AND_ASSIGN(ThreadLogsManager);
+};
+
+}  // namespace cygprofile
+
+#endif  // TOOLS_CYGPROFILE_CYGPROFILE_H_
diff --git a/tools/cygprofile/cygprofile_unittest.cc b/tools/cygprofile/cygprofile_unittest.cc
new file mode 100644
index 0000000..7a1a3e2
--- /dev/null
+++ b/tools/cygprofile/cygprofile_unittest.cc
@@ -0,0 +1,101 @@
+// Copyright 2014 The Chromium Authors. All rights reserved.
+// Use of this source code is governed by a BSD-style license that can be
+// found in the LICENSE file.
+
+#include "tools/cygprofile/cygprofile.h"
+
+#include <vector>
+
+#include <sys/time.h>
+
+#include "base/bind.h"
+#include "base/callback.h"
+#include "base/logging.h"
+#include "base/synchronization/waitable_event.h"
+#include "testing/gtest/include/gtest/gtest.h"
+
+namespace cygprofile {
+namespace {
+
+void FlushEntries(std::vector<LogEntry>* destination,
+                  std::vector<LogEntry>* entries) {
+  CHECK_EQ(0U, destination->size());
+  // Move the provided |entries| vector to the provided |destination| so that
+  // the unit test that triggered the flush can check it.
+  destination->swap(*entries);
+}
+
+// Flush callback that should not be invoked.
+void CheckFlushDoesNotHappen(std::vector<LogEntry>* entries) {
+  NOTREACHED();
+}
+
+uint64_t GetUsecSecTimeFromTimeSpec(struct timespec timespec) {
+  return timespec.tv_sec * 1000 * 1000 + timespec.tv_nsec / 1000;
+}
+
+TEST(CygprofileTest, ThreadLogBasic) {
+  ThreadLog thread_log(base::Bind(&CheckFlushDoesNotHappen));
+
+  thread_log.AddEntry(reinterpret_cast<void*>(0x2));
+  thread_log.AddEntry(reinterpret_cast<void*>(0x1));
+
+  std::vector<LogEntry> entries;
+  thread_log.TakeEntries(&entries);
+
+  ASSERT_EQ(2U, entries.size());
+  // The entries should appear in their insertion order.
+  const LogEntry& first_entry = entries[0];
+  ASSERT_EQ(reinterpret_cast<int>(first_entry.address), 2);
+  ASSERT_EQ(getpid(), first_entry.pid);
+  ASSERT_LT(0, first_entry.tid);
+
+  const LogEntry& second_entry = entries[1];
+  ASSERT_EQ(1, reinterpret_cast<int>(second_entry.address));
+  ASSERT_EQ(first_entry.pid, second_entry.pid);
+  ASSERT_EQ(first_entry.tid, second_entry.tid);
+
+  ASSERT_GE(GetUsecSecTimeFromTimeSpec(second_entry.time),
+            GetUsecSecTimeFromTimeSpec(first_entry.time));
+}
+
+TEST(CygprofileTest, ManagerBasic) {
+  base::WaitableEvent wait_event(true, false);
+  base::WaitableEvent notify_event(true, false);
+
+  ThreadLogsManager manager(
+      base::Bind(&base::WaitableEvent::Wait, base::Unretained(&wait_event)),
+      base::Bind(&base::WaitableEvent::Signal,
+                 base::Unretained(&notify_event)));
+
+  std::vector<LogEntry> entries;
+  scoped_ptr<ThreadLog> thread_log(
+      new ThreadLog(base::Bind(&FlushEntries, base::Unretained(&entries))));
+
+  thread_log->AddEntry(reinterpret_cast<void*>(0x2));
+  thread_log->AddEntry(reinterpret_cast<void*>(0x3));
+
+  // This should make the manager spawn its internal flush thread which will
+  // wait for a notification before it starts doing some work.
+  manager.AddLog(thread_log.Pass());
+
+  EXPECT_EQ(0U, entries.size());
+  // This will wake up the internal thread.
+  wait_event.Signal();
+  // Now it's our turn to wait until it performed the flush.
+  notify_event.Wait();
+
+  // The flush should have moved the data to the local vector of entries.
+  EXPECT_EQ(2U, entries.size());
+  ASSERT_EQ(2, reinterpret_cast<int>(entries[0].address));
+  ASSERT_EQ(3, reinterpret_cast<int>(entries[1].address));
+}
+
+}  // namespace
+}  // namespace cygprofile
+
+// Custom runner implementation since base's one requires JNI on Android.
+int main(int argc, char** argv) {
+  testing::InitGoogleTest(&argc, argv);
+  return RUN_ALL_TESTS();
+}