OLD | NEW |
---|---|
1 // Copyright (c) 2011 The Chromium Authors. All rights reserved. | 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 | 2 // Use of this source code is governed by a BSD-style license that can be |
3 // found in the LICENSE file. | 3 // found in the LICENSE file. |
4 // | 4 // |
5 // Tool to log the execution of the process (Chrome). Writes logs containing | 5 // Tool to log the execution of the process (Chrome). Writes logs containing |
6 // time and address of the callback being called for the first time. | 6 // time and address of the callback being called for the first time. |
7 // | 7 // |
8 // To speed up the logging, buffering logs is implemented. Every thread have its | 8 // To speed up the logging, buffering logs is implemented. Every thread have its |
9 // own buffer and log file so the contention between threads is minimal. As a | 9 // own buffer and log file so the contention between threads is minimal. As a |
10 // side-effect, functions called might be mentioned in many thread logs. | 10 // side-effect, functions called might be mentioned in many thread logs. |
(...skipping 14 matching lines...) Expand all Loading... | |
25 | 25 |
26 #include <fcntl.h> | 26 #include <fcntl.h> |
27 #include <fstream> | 27 #include <fstream> |
28 #include <pthread.h> | 28 #include <pthread.h> |
29 #include <stdarg.h> | 29 #include <stdarg.h> |
30 #include <string> | 30 #include <string> |
31 #include <sys/stat.h> | 31 #include <sys/stat.h> |
32 #include <sys/syscall.h> | 32 #include <sys/syscall.h> |
33 #include <sys/time.h> | 33 #include <sys/time.h> |
34 #include <sys/types.h> | 34 #include <sys/types.h> |
35 #include <unordered_set> | |
36 #include <vector> | 35 #include <vector> |
37 | 36 |
37 #include "base/hash_tables.h" | |
38 #include "base/lazy_instance.h" | 38 #include "base/lazy_instance.h" |
39 #include "base/logging.h" | 39 #include "base/logging.h" |
40 #include "base/memory/singleton.h" | 40 #include "base/memory/singleton.h" |
41 #include "base/synchronization/lock.h" | 41 #include "base/synchronization/lock.h" |
42 | 42 |
43 namespace cygprofile { | 43 namespace cygprofile { |
44 | 44 |
45 extern "C" { | 45 extern "C" { |
46 | 46 |
47 // Note that these are linked internally by the compiler. Don't call | 47 // Note that these are linked internally by the compiler. Don't call |
(...skipping 76 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
124 // A lock that guards buf_ usage between per-thread instrumentation | 124 // A lock that guards buf_ usage between per-thread instrumentation |
125 // routine and timer flush callback. So the contention could happen | 125 // routine and timer flush callback. So the contention could happen |
126 // only during the flush, every 30 secs. | 126 // only during the flush, every 30 secs. |
127 base::Lock log_mutex_; | 127 base::Lock log_mutex_; |
128 | 128 |
129 // Current thread is inside the instrumentation routine. | 129 // Current thread is inside the instrumentation routine. |
130 bool in_use_; | 130 bool in_use_; |
131 | 131 |
132 // Keeps track of all functions that have been logged on this thread | 132 // Keeps track of all functions that have been logged on this thread |
133 // so we do not record dublicates. | 133 // so we do not record dublicates. |
134 std::unordered_set<void*> functions_called_; | 134 std::hash_set<void*> functions_called_; |
135 | 135 |
136 // Thread identifier as Linux kernel shows it. For debugging purposes. | 136 // Thread identifier as Linux kernel shows it. For debugging purposes. |
137 // LWP (light-weight process) is a unique ID of the thread in the system, | 137 // LWP (light-weight process) is a unique ID of the thread in the system, |
138 // unlike pthread_self() which is the same for fork()-ed threads. | 138 // unlike pthread_self() which is the same for fork()-ed threads. |
139 pid_t lwp_; | 139 pid_t lwp_; |
140 pthread_t pthread_self_; | 140 pthread_t pthread_self_; |
141 | 141 |
142 DISALLOW_COPY_AND_ASSIGN(CygTlsLog); | 142 DISALLOW_COPY_AND_ASSIGN(CygTlsLog); |
143 }; | 143 }; |
144 | 144 |
145 // Storage for logs for all threads in the process. | 145 // Storage for logs for all threads in the process. |
146 // Using std::list may be better, but it fails when used before main(). | 146 // Using std::list may be better, but it fails when used before main(). |
147 struct AllLogs { | 147 struct AllLogs { |
148 std::vector<CygTlsLog*> logs; | 148 std::vector<CygTlsLog*> logs; |
149 base::Lock mutex; | 149 base::Lock mutex; |
150 }; | 150 }; |
151 | 151 |
152 base::LazyInstance<AllLogs>::Leaky all_logs_ = LAZY_INSTANCE_INITIALIZER; | 152 base::LazyInstance<AllLogs>::Leaky all_logs_ = LAZY_INSTANCE_INITIALIZER; |
153 | 153 |
154 // Per-thread pointer to the current log object. | 154 // Per-thread pointer to the current log object. |
155 __thread CygTlsLog* tls_current_log = NULL; | 155 static __thread CygTlsLog* tls_current_log = NULL; |
156 | 156 |
157 // Magic value of above to prevent the instrumentation. Used when CygTlsLog is | 157 // Magic value of above to prevent the instrumentation. Used when CygTlsLog is |
158 // being constructed (to prevent reentering by malloc, for example) and by | 158 // being constructed (to prevent reentering by malloc, for example) and by |
159 // the FlushLogThread (to prevent it being logged - see comment in its code). | 159 // the FlushLogThread (to prevent it being logged - see comment in its code). |
160 CygTlsLog* const kMagicBeingConstructed = reinterpret_cast<CygTlsLog*>(1); | 160 CygTlsLog* const kMagicBeingConstructed = reinterpret_cast<CygTlsLog*>(1); |
161 | 161 |
162 // Number of entries in the per-thread log buffer before we flush. | 162 // Number of entries in the per-thread log buffer before we flush. |
163 // Note, that we also flush by timer so not all thread logs may grow up to this. | 163 // Note, that we also flush by timer so not all thread logs may grow up to this. |
164 const int CygTlsLog::kBufMaxSize = 3000; | 164 const int CygTlsLog::kBufMaxSize = 3000; |
165 | 165 |
166 // "cyglog.PID.LWP.pthread_self.PPID" | 166 // "cyglog.PID.LWP.pthread_self.PPID" |
167 #if defined(OS_ANDROID) | |
bulach
2012/12/03 16:48:30
maybe splitting this would be nicer:
#if defined(
felipeg
2012/12/03 16:56:44
Done.
| |
168 const char CygTlsLog::kLogFilenameFmt[] = | |
169 "/data/local/tmp/chrome/cyglog/cyglog.%d.%d.%ld-%d"; | |
170 #else | |
167 const char CygTlsLog::kLogFilenameFmt[] = "/var/log/chrome/cyglog.%d.%d.%ld-%d"; | 171 const char CygTlsLog::kLogFilenameFmt[] = "/var/log/chrome/cyglog.%d.%d.%ld-%d"; |
172 #endif | |
168 | 173 |
169 CygCommon* CygCommon::GetInstance() { | 174 CygCommon* CygCommon::GetInstance() { |
170 return Singleton<CygCommon>::get(); | 175 return Singleton<CygCommon>::get(); |
171 } | 176 } |
172 | 177 |
173 CygCommon::CygCommon() { | 178 CygCommon::CygCommon() { |
174 // Determine our module addresses. | 179 // Determine our module addresses. |
175 std::ifstream mapsfile("/proc/self/maps"); | 180 std::ifstream mapsfile("/proc/self/maps"); |
176 CHECK(mapsfile.good()); | 181 CHECK(mapsfile.good()); |
177 static const int kMaxLineSize = 512; | 182 static const int kMaxLineSize = 512; |
(...skipping 96 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
274 void CygTlsLog::StartFlushLogThread() { | 279 void CygTlsLog::StartFlushLogThread() { |
275 pthread_t tid; | 280 pthread_t tid; |
276 CHECK(!pthread_create(&tid, NULL, &CygTlsLog::FlushLogThread, NULL)); | 281 CHECK(!pthread_create(&tid, NULL, &CygTlsLog::FlushLogThread, NULL)); |
277 } | 282 } |
278 | 283 |
279 void CygTlsLog::AddNewLog(CygTlsLog* newlog) { | 284 void CygTlsLog::AddNewLog(CygTlsLog* newlog) { |
280 CHECK(tls_current_log == kMagicBeingConstructed); | 285 CHECK(tls_current_log == kMagicBeingConstructed); |
281 AllLogs& all_logs = all_logs_.Get(); | 286 AllLogs& all_logs = all_logs_.Get(); |
282 base::AutoLock lock(all_logs.mutex); | 287 base::AutoLock lock(all_logs.mutex); |
283 if (all_logs.logs.empty()) { | 288 if (all_logs.logs.empty()) { |
289 | |
290 #if !defined(OS_ANDROID) | |
glotov
2012/12/03 16:42:17
Could you please make a simple test that verifies
felipeg
2012/12/03 16:56:44
Done.
glotov
2012/12/03 17:10:08
Well, actually it is up to you. Are you 100% sure
felipeg
2012/12/03 18:51:20
I am 100% sure that we don't fork and we will neve
| |
284 CHECK(!pthread_atfork(CygTlsLog::AtForkPrepare, | 291 CHECK(!pthread_atfork(CygTlsLog::AtForkPrepare, |
285 CygTlsLog::AtForkParent, | 292 CygTlsLog::AtForkParent, |
286 CygTlsLog::AtForkChild)); | 293 CygTlsLog::AtForkChild)); |
294 #endif | |
287 | 295 |
288 // The very first process starts its flush thread here. Forked processes | 296 // The very first process starts its flush thread here. Forked processes |
289 // will do it in AtForkChild(). | 297 // will do it in AtForkChild(). |
290 StartFlushLogThread(); | 298 StartFlushLogThread(); |
291 } | 299 } |
292 all_logs.logs.push_back(newlog); | 300 all_logs.logs.push_back(newlog); |
293 } | 301 } |
294 | 302 |
295 // Printf-style routine to write to open file. | 303 // Printf-style routine to write to open file. |
296 static void WriteLogLine(int fd, const char* fmt, ...) { | 304 static void WriteLogLine(int fd, const char* fmt, ...) { |
297 va_list arg_ptr; | 305 va_list arg_ptr; |
298 va_start(arg_ptr, fmt); | 306 va_start(arg_ptr, fmt); |
299 char msg[160]; | 307 char msg[160]; |
300 int len = vsnprintf(msg, sizeof(msg), fmt, arg_ptr); | 308 int len = vsnprintf(msg, sizeof(msg), fmt, arg_ptr); |
301 int rc = write(fd, msg, (len > sizeof(msg))? sizeof(msg): len); | 309 int rc = write(fd, msg, (len > sizeof(msg))? sizeof(msg): len); |
302 va_end(arg_ptr); | 310 va_end(arg_ptr); |
303 }; | 311 }; |
304 | 312 |
305 void CygTlsLog::FlushLog() { | 313 void CygTlsLog::FlushLog() { |
306 bool first_log_write = false; | 314 bool first_log_write = false; |
307 | |
308 if (log_filename_.empty()) { | 315 if (log_filename_.empty()) { |
309 first_log_write = true; | 316 first_log_write = true; |
310 char buf[80]; | 317 char buf[80]; |
311 snprintf(buf, sizeof(buf), kLogFilenameFmt, | 318 snprintf(buf, sizeof(buf), kLogFilenameFmt, |
312 getpid(), lwp_, pthread_self_, getppid()); | 319 getpid(), lwp_, pthread_self_, getppid()); |
313 log_filename_ = buf; | 320 log_filename_ = buf; |
314 unlink(log_filename_.c_str()); | 321 unlink(log_filename_.c_str()); |
315 } | 322 } |
316 | 323 |
317 int file = open(log_filename_.c_str(), O_CREAT | O_WRONLY | O_APPEND, 00600); | 324 int file = open(log_filename_.c_str(), O_CREAT | O_WRONLY | O_APPEND, 00600); |
(...skipping 59 matching lines...) Expand 10 before | Expand all | Expand 10 after Loading... | |
377 tls_current_log->LogEnter(this_fn); | 384 tls_current_log->LogEnter(this_fn); |
378 } | 385 } |
379 } | 386 } |
380 | 387 |
381 // Gcc Compiler callback, called after every function invocation providing | 388 // Gcc Compiler callback, called after every function invocation providing |
382 // addresses of caller and callee codes. | 389 // addresses of caller and callee codes. |
383 void __cyg_profile_func_exit(void* this_fn, void* call_site) { | 390 void __cyg_profile_func_exit(void* this_fn, void* call_site) { |
384 } | 391 } |
385 | 392 |
386 } // namespace cygprofile | 393 } // namespace cygprofile |
OLD | NEW |