1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
|
// 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.
#include "tools/cygprofile/cygprofile.h"
#include <fcntl.h>
#include <pthread.h>
#include <stddef.h>
#include <stdint.h>
#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/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 {
// Allow 8 MBytes of data for each thread log.
const size_t kMaxBufferSize = 8 * 1024 * 1024 / sizeof(LogEntry);
// Have the background internal thread do its flush every 15 sec.
const int kFlushThreadIdleTimeSec = 15;
const char kLogFileNamePrefix[] = "/data/local/tmp/chrome/cyglog/";
// "cyglog.PID.LWP.PPID"
const char kLogFilenameFormat[] = "%scyglog.%d.%d-%d";
// 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);
// 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.
pid_t GetTID() {
return syscall(__NR_gettid);
}
timespec GetCurrentTime() {
timespec timestamp;
clock_gettime(CLOCK_MONOTONIC, ×tamp);
return timestamp;
}
// 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);
}
// 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()) {}
const std::string value;
private:
// 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,
size_t start_offset,
size_t length,
uint64_t* result) {
if (start_offset >= line.length())
return false;
uint64_t address;
const bool ret = HexStringToUInt64(
base::StringPiece(line.c_str() + start_offset, length), &address);
if (!ret)
return false;
*result = address;
return true;
}
// 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_t start_address = 0;
CHECK(ParseAddress(line, 0, address_length, &start_address));
uint64_t 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;
}
};
base::LazyInstance<ThreadLogsManager>::Leaky g_logs_manager =
LAZY_INSTANCE_INITIALIZER;
base::LazyInstance<ImmutableFileHeaderLine>::Leaky g_file_header_line =
LAZY_INSTANCE_INITIALIZER;
} // namespace
// 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));
}
~Thread() {
CHECK_EQ(0, pthread_join(handle_, NULL));
}
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;
}
const base::Closure thread_callback_;
pthread_t handle_;
DISALLOW_COPY_AND_ASSIGN(Thread);
};
// Single log entry recorded for each function call.
LogEntry::LogEntry(const void* address)
: time(GetCurrentTime()),
pid(getpid()),
tid(GetTID()),
address(address) {
}
ThreadLog::ThreadLog()
: tid_(GetTID()),
in_use_(false),
flush_callback_(
base::Bind(&ThreadLog::FlushInternal, base::Unretained(this))) {
}
ThreadLog::ThreadLog(const FlushCallback& flush_callback)
: tid_(GetTID()),
in_use_(false),
flush_callback_(flush_callback) {
}
ThreadLog::~ThreadLog() {
g_tls_log = NULL;
}
void ThreadLog::AddEntry(void* address) {
if (in_use_)
return;
in_use_ = true;
CHECK_EQ(tid_, GetTID());
const std::pair<base::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 ThreadLog::TakeEntries(std::vector<LogEntry>* destination) {
base::AutoLock auto_lock(lock_);
destination->swap(entries_);
STLClearObject(&entries_);
}
void ThreadLog::Flush(std::vector<LogEntry>* entries) const {
flush_callback_.Run(entries);
}
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:%d\t%p\n", it->time.tv_sec,
it->time.tv_nsec / 1000, it->pid, it->tid, it->address);
}
STLClearObject(entries);
}
ThreadLogsManager::ThreadLogsManager()
: wait_callback_(base::Bind(&SleepSec, kFlushThreadIdleTimeSec)) {
}
ThreadLogsManager::ThreadLogsManager(const base::Closure& wait_callback,
const base::Closure& notify_callback)
: wait_callback_(wait_callback),
notify_callback_(notify_callback) {
}
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.
STLDeleteContainerPointers(logs_.begin(), logs_.end());
}
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 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))));
}
// Type used below for flushing.
struct LogData {
LogData(ThreadLog* thread_log) : thread_log(thread_log) {}
ThreadLog* const thread_log;
std::vector<LogEntry> entries;
};
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_;
}
// 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);
}
for (std::vector<LogData>::iterator it = logs.begin();
it != logs.end(); ++it) {
if (!it->entries.empty())
it->thread_log->Flush(&it->entries);
}
if (!notify_callback_.is_null())
notify_callback_.Run();
}
}
extern "C" {
// 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 (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 (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
|