blob: 06e74b846294d0acafdb9194e6e2a5201c27d8e0 [file] [log] [blame]
// 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 linux_use_tcmalloc=0.
// Note for the ChromeOS Chrome. Remove renderer process from the sandbox (add
// --no-sandbox option to running Chrome in /sbin/
// 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 <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 <vector>
#include "base/containers/hash_tables.h"
#include "base/lazy_instance.h"
#include "base/logging.h"
#include "base/memory/singleton.h"
#include "base/synchronization/lock.h"
namespace cygprofile {
extern "C" {
// 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)
void __cyg_profile_func_exit(void* this_fn, void* call_site)
// 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) {}
// Common data for the process. Singleton.
class CygCommon {
static CygCommon* GetInstance();
std::string header() const { return header_line_; }
std::string header_line_;
friend struct DefaultSingletonTraits<CygCommon>;
// Returns light-weight process ID. On linux, this is a system-wide
// unique thread id.
static pid_t GetLwp() {
return syscall(__NR_gettid);
// A per-thread structure representing the log itself.
class CygTlsLog {
: in_use_(false), lwp_(GetLwp()), pthread_self_(pthread_self()) { }
// Enter a log entity.
void LogEnter(void* this_fn);
// 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);
// Starts a thread in this process that periodically flushes all the threads.
// Must be called once per process.
static void StartFlushLogThread();
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();
// Fork hooks. Needed to keep data in consistent state during fork().
static void AtForkPrepare();
static void AtForkParent();
static void AtForkChild();
// Thread callback to flush all logs periodically.
static void* FlushLogThread(void*);
std::string log_filename_;
std::vector<CygLogEntry> buf_;
// 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_;
// Current thread is inside the instrumentation routine.
bool in_use_;
// 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 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_;
// 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;
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[] =
const char CygTlsLog::kLogFileNamePrefix[] = "/var/log/chrome/";
// "cyglog.PID.LWP.pthread_self.PPID"
const char CygTlsLog::kLogFilenameFmt[] = "%scyglog.%d.%d.%ld-%d";
CygCommon* CygCommon::GetInstance() {
return Singleton<CygCommon>::get();
CygCommon::CygCommon() {
// Determine our module addresses.
std::ifstream mapsfile("/proc/self/maps");
static const int kMaxLineSize = 512;
char line[kMaxLineSize];
void (*this_fn)(void) =
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;
void CygTlsLog::LogEnter(void* this_fn) {
if (in_use_)
in_use_ = true;
if (functions_called_.find(this_fn) ==
functions_called_.end()) {
base::AutoLock lock(log_mutex_);
if (buf_.capacity() < kBufMaxSize)
struct timeval timestamp;
gettimeofday(&timestamp, NULL);
buf_.push_back(CygLogEntry(time(NULL), timestamp.tv_usec,
getpid(), pthread_self(), this_fn));
if (buf_.size() == kBufMaxSize) {
in_use_ = false;
void CygTlsLog::AtForkPrepare() {
CHECK(tls_current_log->lwp_ == GetLwp());
CHECK(tls_current_log->pthread_self_ == pthread_self());
void CygTlsLog::AtForkParent() {
CHECK(tls_current_log->lwp_ == GetLwp());
CHECK(tls_current_log->pthread_self_ == pthread_self());
void CygTlsLog::AtForkChild() {
// 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;
CHECK(tls_current_log->pthread_self_ == pthread_self());
// 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();
CHECK(all_logs.logs.size() == 1);
// Clear log filename so it will be re-calculated with the new PIDs.
// Create the thread that will periodically flush all logs for this process.
// We do not update log header line (CygCommon data) as it will be the same
// because the new process is just a forked copy.
void CygTlsLog::StartFlushLogThread() {
pthread_t tid;
CHECK(!pthread_create(&tid, NULL, &CygTlsLog::FlushLogThread, NULL));
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)
// The very first process starts its flush thread here. Forked processes
// will do it in AtForkChild().
// 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);
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;
int file = open(log_filename_.c_str(), O_CREAT | O_WRONLY | O_APPEND, 00600);
CHECK(file != -1);
if (first_log_write)
WriteLogLine(file, "%s", CygCommon::GetInstance()->header().c_str());
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.tid, p.this_fn);
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()) {
} 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().
// Gcc Compiler callback, called on every function invocation providing
// addresses of caller and callee codes.
void __cyg_profile_func_enter(void* this_fn, void* callee_unused) {
if (tls_current_log == NULL) {
tls_current_log = kMagicBeingConstructed;
CygTlsLog* newlog = new CygTlsLog;
tls_current_log = newlog;
if (tls_current_log != kMagicBeingConstructed) {
// 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) {
} // namespace cygprofile