1 /*
2 * Copyright (C) 2012 The Android Open Source Project
3 *
4 * Licensed under the Apache License, Version 2.0 (the "License");
5 * you may not use this file except in compliance with the License.
6 * You may obtain a copy of the License at
7 *
8 * http://www.apache.org/licenses/LICENSE-2.0
9 *
10 * Unless required by applicable law or agreed to in writing, software
11 * distributed under the License is distributed on an "AS IS" BASIS,
12 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
13 * See the License for the specific language governing permissions and
14 * limitations under the License.
15 */
16
17 #define LOG_TAG "atrace"
18
19 #include <errno.h>
20 #include <fcntl.h>
21 #include <getopt.h>
22 #include <inttypes.h>
23 #include <signal.h>
24 #include <stdarg.h>
25 #include <stdbool.h>
26 #include <stdio.h>
27 #include <stdlib.h>
28 #include <string.h>
29 #include <sys/sendfile.h>
30 #include <time.h>
31 #include <unistd.h>
32 #include <zlib.h>
33
34 #include <fstream>
35 #include <memory>
36
37 #include <binder/IBinder.h>
38 #include <binder/IServiceManager.h>
39 #include <binder/Parcel.h>
40
41 #include <android/hidl/manager/1.0/IServiceManager.h>
42 #include <hidl/ServiceManagement.h>
43 #include <cutils/properties.h>
44
45 #include <utils/String8.h>
46 #include <utils/Timers.h>
47 #include <utils/Tokenizer.h>
48 #include <utils/Trace.h>
49 #include <android-base/file.h>
50
51 using namespace android;
52
53 using std::string;
54 #define NELEM(x) ((int) (sizeof(x) / sizeof((x)[0])))
55
56 #define MAX_SYS_FILES 10
57 #define MAX_PACKAGES 16
58
59 const char* k_traceTagsProperty = "debug.atrace.tags.enableflags";
60
61 const char* k_traceAppsNumberProperty = "debug.atrace.app_number";
62 const char* k_traceAppsPropertyTemplate = "debug.atrace.app_%d";
63 const char* k_coreServiceCategory = "core_services";
64 const char* k_coreServicesProp = "ro.atrace.core.services";
65
66 typedef enum { OPT, REQ } requiredness ;
67
68 struct TracingCategory {
69 // The name identifying the category.
70 const char* name;
71
72 // A longer description of the category.
73 const char* longname;
74
75 // The userland tracing tags that the category enables.
76 uint64_t tags;
77
78 // The fname==NULL terminated list of /sys/ files that the category
79 // enables.
80 struct {
81 // Whether the file must be writable in order to enable the tracing
82 // category.
83 requiredness required;
84
85 // The path to the enable file.
86 const char* path;
87 } sysfiles[MAX_SYS_FILES];
88 };
89
90 /* Tracing categories */
91 static const TracingCategory k_categories[] = {
92 { "gfx", "Graphics", ATRACE_TAG_GRAPHICS, { } },
93 { "input", "Input", ATRACE_TAG_INPUT, { } },
94 { "view", "View System", ATRACE_TAG_VIEW, { } },
95 { "webview", "WebView", ATRACE_TAG_WEBVIEW, { } },
96 { "wm", "Window Manager", ATRACE_TAG_WINDOW_MANAGER, { } },
97 { "am", "Activity Manager", ATRACE_TAG_ACTIVITY_MANAGER, { } },
98 { "sm", "Sync Manager", ATRACE_TAG_SYNC_MANAGER, { } },
99 { "audio", "Audio", ATRACE_TAG_AUDIO, { } },
100 { "video", "Video", ATRACE_TAG_VIDEO, { } },
101 { "camera", "Camera", ATRACE_TAG_CAMERA, { } },
102 { "hal", "Hardware Modules", ATRACE_TAG_HAL, { } },
103 { "app", "Application", ATRACE_TAG_APP, { } },
104 { "res", "Resource Loading", ATRACE_TAG_RESOURCES, { } },
105 { "dalvik", "Dalvik VM", ATRACE_TAG_DALVIK, { } },
106 { "rs", "RenderScript", ATRACE_TAG_RS, { } },
107 { "bionic", "Bionic C Library", ATRACE_TAG_BIONIC, { } },
108 { "power", "Power Management", ATRACE_TAG_POWER, { } },
109 { "pm", "Package Manager", ATRACE_TAG_PACKAGE_MANAGER, { } },
110 { "ss", "System Server", ATRACE_TAG_SYSTEM_SERVER, { } },
111 { "database", "Database", ATRACE_TAG_DATABASE, { } },
112 { "network", "Network", ATRACE_TAG_NETWORK, { } },
113 { "adb", "ADB", ATRACE_TAG_ADB, { } },
114 { k_coreServiceCategory, "Core services", 0, { } },
115 { "sched", "CPU Scheduling", 0, {
116 { REQ, "events/sched/sched_switch/enable" },
117 { REQ, "events/sched/sched_wakeup/enable" },
118 { OPT, "events/sched/sched_waking/enable" },
119 { OPT, "events/sched/sched_blocked_reason/enable" },
120 { OPT, "events/sched/sched_cpu_hotplug/enable" },
121 } },
122 { "irq", "IRQ Events", 0, {
123 { REQ, "events/irq/enable" },
124 { OPT, "events/ipi/enable" },
125 } },
126 { "i2c", "I2C Events", 0, {
127 { REQ, "events/i2c/enable" },
128 { REQ, "events/i2c/i2c_read/enable" },
129 { REQ, "events/i2c/i2c_write/enable" },
130 { REQ, "events/i2c/i2c_result/enable" },
131 { REQ, "events/i2c/i2c_reply/enable" },
132 { OPT, "events/i2c/smbus_read/enable" },
133 { OPT, "events/i2c/smbus_write/enable" },
134 { OPT, "events/i2c/smbus_result/enable" },
135 { OPT, "events/i2c/smbus_reply/enable" },
136 } },
137 { "freq", "CPU Frequency", 0, {
138 { REQ, "events/power/cpu_frequency/enable" },
139 { OPT, "events/power/clock_set_rate/enable" },
140 { OPT, "events/power/cpu_frequency_limits/enable" },
141 } },
142 { "membus", "Memory Bus Utilization", 0, {
143 { REQ, "events/memory_bus/enable" },
144 } },
145 { "idle", "CPU Idle", 0, {
146 { REQ, "events/power/cpu_idle/enable" },
147 } },
148 { "disk", "Disk I/O", 0, {
149 { OPT, "events/f2fs/f2fs_sync_file_enter/enable" },
150 { OPT, "events/f2fs/f2fs_sync_file_exit/enable" },
151 { OPT, "events/f2fs/f2fs_write_begin/enable" },
152 { OPT, "events/f2fs/f2fs_write_end/enable" },
153 { OPT, "events/ext4/ext4_da_write_begin/enable" },
154 { OPT, "events/ext4/ext4_da_write_end/enable" },
155 { OPT, "events/ext4/ext4_sync_file_enter/enable" },
156 { OPT, "events/ext4/ext4_sync_file_exit/enable" },
157 { REQ, "events/block/block_rq_issue/enable" },
158 { REQ, "events/block/block_rq_complete/enable" },
159 } },
160 { "mmc", "eMMC commands", 0, {
161 { REQ, "events/mmc/enable" },
162 } },
163 { "load", "CPU Load", 0, {
164 { REQ, "events/cpufreq_interactive/enable" },
165 } },
166 { "sync", "Synchronization", 0, {
167 { REQ, "events/sync/enable" },
168 } },
169 { "workq", "Kernel Workqueues", 0, {
170 { REQ, "events/workqueue/enable" },
171 } },
172 { "memreclaim", "Kernel Memory Reclaim", 0, {
173 { REQ, "events/vmscan/mm_vmscan_direct_reclaim_begin/enable" },
174 { REQ, "events/vmscan/mm_vmscan_direct_reclaim_end/enable" },
175 { REQ, "events/vmscan/mm_vmscan_kswapd_wake/enable" },
176 { REQ, "events/vmscan/mm_vmscan_kswapd_sleep/enable" },
177 } },
178 { "regulators", "Voltage and Current Regulators", 0, {
179 { REQ, "events/regulator/enable" },
180 } },
181 { "binder_driver", "Binder Kernel driver", 0, {
182 { REQ, "events/binder/binder_transaction/enable" },
183 { REQ, "events/binder/binder_transaction_received/enable" },
184 } },
185 { "binder_lock", "Binder global lock trace", 0, {
186 { REQ, "events/binder/binder_lock/enable" },
187 { REQ, "events/binder/binder_locked/enable" },
188 { REQ, "events/binder/binder_unlock/enable" },
189 } },
190 { "pagecache", "Page cache", 0, {
191 { REQ, "events/filemap/enable" },
192 } },
193 };
194
195 /* Command line options */
196 static int g_traceDurationSeconds = 5;
197 static bool g_traceOverwrite = false;
198 static int g_traceBufferSizeKB = 2048;
199 static bool g_compress = false;
200 static bool g_nohup = false;
201 static int g_initialSleepSecs = 0;
202 static const char* g_categoriesFile = NULL;
203 static const char* g_kernelTraceFuncs = NULL;
204 static const char* g_debugAppCmdLine = "";
205 static const char* g_outputFile = nullptr;
206
207 /* Global state */
208 static bool g_traceAborted = false;
209 static bool g_categoryEnables[NELEM(k_categories)] = {};
210 static std::string g_traceFolder;
211
212 /* Sys file paths */
213 static const char* k_traceClockPath =
214 "trace_clock";
215
216 static const char* k_traceBufferSizePath =
217 "buffer_size_kb";
218
219 static const char* k_traceCmdlineSizePath =
220 "saved_cmdlines_size";
221
222 static const char* k_tracingOverwriteEnablePath =
223 "options/overwrite";
224
225 static const char* k_currentTracerPath =
226 "current_tracer";
227
228 static const char* k_printTgidPath =
229 "options/print-tgid";
230
231 static const char* k_funcgraphAbsTimePath =
232 "options/funcgraph-abstime";
233
234 static const char* k_funcgraphCpuPath =
235 "options/funcgraph-cpu";
236
237 static const char* k_funcgraphProcPath =
238 "options/funcgraph-proc";
239
240 static const char* k_funcgraphFlatPath =
241 "options/funcgraph-flat";
242
243 static const char* k_funcgraphDurationPath =
244 "options/funcgraph-duration";
245
246 static const char* k_ftraceFilterPath =
247 "set_ftrace_filter";
248
249 static const char* k_tracingOnPath =
250 "tracing_on";
251
252 static const char* k_tracePath =
253 "trace";
254
255 static const char* k_traceStreamPath =
256 "trace_pipe";
257
258 static const char* k_traceMarkerPath =
259 "trace_marker";
260
261 // Check whether a file exists.
fileExists(const char * filename)262 static bool fileExists(const char* filename) {
263 return access((g_traceFolder + filename).c_str(), F_OK) != -1;
264 }
265
266 // Check whether a file is writable.
fileIsWritable(const char * filename)267 static bool fileIsWritable(const char* filename) {
268 return access((g_traceFolder + filename).c_str(), W_OK) != -1;
269 }
270
271 // Truncate a file.
truncateFile(const char * path)272 static bool truncateFile(const char* path)
273 {
274 // This uses creat rather than truncate because some of the debug kernel
275 // device nodes (e.g. k_ftraceFilterPath) currently aren't changed by
276 // calls to truncate, but they are cleared by calls to creat.
277 int traceFD = creat((g_traceFolder + path).c_str(), 0);
278 if (traceFD == -1) {
279 fprintf(stderr, "error truncating %s: %s (%d)\n", (g_traceFolder + path).c_str(),
280 strerror(errno), errno);
281 return false;
282 }
283
284 close(traceFD);
285
286 return true;
287 }
288
_writeStr(const char * filename,const char * str,int flags)289 static bool _writeStr(const char* filename, const char* str, int flags)
290 {
291 std::string fullFilename = g_traceFolder + filename;
292 int fd = open(fullFilename.c_str(), flags);
293 if (fd == -1) {
294 fprintf(stderr, "error opening %s: %s (%d)\n", fullFilename.c_str(),
295 strerror(errno), errno);
296 return false;
297 }
298
299 bool ok = true;
300 ssize_t len = strlen(str);
301 if (write(fd, str, len) != len) {
302 fprintf(stderr, "error writing to %s: %s (%d)\n", fullFilename.c_str(),
303 strerror(errno), errno);
304 ok = false;
305 }
306
307 close(fd);
308
309 return ok;
310 }
311
312 // Write a string to a file, returning true if the write was successful.
writeStr(const char * filename,const char * str)313 static bool writeStr(const char* filename, const char* str)
314 {
315 return _writeStr(filename, str, O_WRONLY);
316 }
317
318 // Append a string to a file, returning true if the write was successful.
appendStr(const char * filename,const char * str)319 static bool appendStr(const char* filename, const char* str)
320 {
321 return _writeStr(filename, str, O_APPEND|O_WRONLY);
322 }
323
writeClockSyncMarker()324 static void writeClockSyncMarker()
325 {
326 char buffer[128];
327 int len = 0;
328 int fd = open((g_traceFolder + k_traceMarkerPath).c_str(), O_WRONLY);
329 if (fd == -1) {
330 fprintf(stderr, "error opening %s: %s (%d)\n", k_traceMarkerPath,
331 strerror(errno), errno);
332 return;
333 }
334 float now_in_seconds = systemTime(CLOCK_MONOTONIC) / 1000000000.0f;
335
336 len = snprintf(buffer, 128, "trace_event_clock_sync: parent_ts=%f\n", now_in_seconds);
337 if (write(fd, buffer, len) != len) {
338 fprintf(stderr, "error writing clock sync marker %s (%d)\n", strerror(errno), errno);
339 }
340
341 int64_t realtime_in_ms = systemTime(CLOCK_REALTIME) / 1000000;
342 len = snprintf(buffer, 128, "trace_event_clock_sync: realtime_ts=%" PRId64 "\n", realtime_in_ms);
343 if (write(fd, buffer, len) != len) {
344 fprintf(stderr, "error writing clock sync marker %s (%d)\n", strerror(errno), errno);
345 }
346
347 close(fd);
348 }
349
350 // Enable or disable a kernel option by writing a "1" or a "0" into a /sys
351 // file.
setKernelOptionEnable(const char * filename,bool enable)352 static bool setKernelOptionEnable(const char* filename, bool enable)
353 {
354 return writeStr(filename, enable ? "1" : "0");
355 }
356
357 // Check whether the category is supported on the device with the current
358 // rootness. A category is supported only if all its required /sys/ files are
359 // writable and if enabling the category will enable one or more tracing tags
360 // or /sys/ files.
isCategorySupported(const TracingCategory & category)361 static bool isCategorySupported(const TracingCategory& category)
362 {
363 if (strcmp(category.name, k_coreServiceCategory) == 0) {
364 char value[PROPERTY_VALUE_MAX];
365 property_get(k_coreServicesProp, value, "");
366 return strlen(value) != 0;
367 }
368
369 bool ok = category.tags != 0;
370 for (int i = 0; i < MAX_SYS_FILES; i++) {
371 const char* path = category.sysfiles[i].path;
372 bool req = category.sysfiles[i].required == REQ;
373 if (path != NULL) {
374 if (req) {
375 if (!fileIsWritable(path)) {
376 return false;
377 } else {
378 ok = true;
379 }
380 } else {
381 ok |= fileIsWritable(path);
382 }
383 }
384 }
385 return ok;
386 }
387
388 // Check whether the category would be supported on the device if the user
389 // were root. This function assumes that root is able to write to any file
390 // that exists. It performs the same logic as isCategorySupported, but it
391 // uses file existence rather than writability in the /sys/ file checks.
isCategorySupportedForRoot(const TracingCategory & category)392 static bool isCategorySupportedForRoot(const TracingCategory& category)
393 {
394 bool ok = category.tags != 0;
395 for (int i = 0; i < MAX_SYS_FILES; i++) {
396 const char* path = category.sysfiles[i].path;
397 bool req = category.sysfiles[i].required == REQ;
398 if (path != NULL) {
399 if (req) {
400 if (!fileExists(path)) {
401 return false;
402 } else {
403 ok = true;
404 }
405 } else {
406 ok |= fileExists(path);
407 }
408 }
409 }
410 return ok;
411 }
412
413 // Enable or disable overwriting of the kernel trace buffers. Disabling this
414 // will cause tracing to stop once the trace buffers have filled up.
setTraceOverwriteEnable(bool enable)415 static bool setTraceOverwriteEnable(bool enable)
416 {
417 return setKernelOptionEnable(k_tracingOverwriteEnablePath, enable);
418 }
419
420 // Enable or disable kernel tracing.
setTracingEnabled(bool enable)421 static bool setTracingEnabled(bool enable)
422 {
423 return setKernelOptionEnable(k_tracingOnPath, enable);
424 }
425
426 // Clear the contents of the kernel trace.
clearTrace()427 static bool clearTrace()
428 {
429 return truncateFile(k_tracePath);
430 }
431
432 // Set the size of the kernel's trace buffer in kilobytes.
setTraceBufferSizeKB(int size)433 static bool setTraceBufferSizeKB(int size)
434 {
435 char str[32] = "1";
436 int len;
437 if (size < 1) {
438 size = 1;
439 }
440 snprintf(str, 32, "%d", size);
441 return writeStr(k_traceBufferSizePath, str);
442 }
443
444 // Set the default size of cmdline hashtable
setCmdlineSize()445 static bool setCmdlineSize()
446 {
447 if (fileExists(k_traceCmdlineSizePath)) {
448 return writeStr(k_traceCmdlineSizePath, "8192");
449 }
450 return true;
451 }
452
453 // Set the clock to the best available option while tracing. Use 'boot' if it's
454 // available; otherwise, use 'mono'. If neither are available use 'global'.
455 // Any write to the trace_clock sysfs file will reset the buffer, so only
456 // update it if the requested value is not the current value.
setClock()457 static bool setClock()
458 {
459 std::ifstream clockFile((g_traceFolder + k_traceClockPath).c_str(), O_RDONLY);
460 std::string clockStr((std::istreambuf_iterator<char>(clockFile)),
461 std::istreambuf_iterator<char>());
462
463 std::string newClock;
464 if (clockStr.find("boot") != std::string::npos) {
465 newClock = "boot";
466 } else if (clockStr.find("mono") != std::string::npos) {
467 newClock = "mono";
468 } else {
469 newClock = "global";
470 }
471
472 size_t begin = clockStr.find("[") + 1;
473 size_t end = clockStr.find("]");
474 if (newClock.compare(0, std::string::npos, clockStr, begin, end-begin) == 0) {
475 return true;
476 }
477 return writeStr(k_traceClockPath, newClock.c_str());
478 }
479
setPrintTgidEnableIfPresent(bool enable)480 static bool setPrintTgidEnableIfPresent(bool enable)
481 {
482 if (fileExists(k_printTgidPath)) {
483 return setKernelOptionEnable(k_printTgidPath, enable);
484 }
485 return true;
486 }
487
488 // Poke all the binder-enabled processes in the system to get them to re-read
489 // their system properties.
pokeBinderServices()490 static bool pokeBinderServices()
491 {
492 sp<IServiceManager> sm = defaultServiceManager();
493 Vector<String16> services = sm->listServices();
494 for (size_t i = 0; i < services.size(); i++) {
495 sp<IBinder> obj = sm->checkService(services[i]);
496 if (obj != NULL) {
497 Parcel data;
498 if (obj->transact(IBinder::SYSPROPS_TRANSACTION, data,
499 NULL, 0) != OK) {
500 if (false) {
501 // XXX: For some reason this fails on tablets trying to
502 // poke the "phone" service. It's not clear whether some
503 // are expected to fail.
504 String8 svc(services[i]);
505 fprintf(stderr, "error poking binder service %s\n",
506 svc.string());
507 return false;
508 }
509 }
510 }
511 }
512 return true;
513 }
514
515 // Poke all the HAL processes in the system to get them to re-read
516 // their system properties.
pokeHalServices()517 static void pokeHalServices()
518 {
519 using ::android::hidl::base::V1_0::IBase;
520 using ::android::hidl::manager::V1_0::IServiceManager;
521 using ::android::hardware::hidl_string;
522 using ::android::hardware::Return;
523
524 sp<IServiceManager> sm = ::android::hardware::defaultServiceManager();
525
526 if (sm == nullptr) {
527 fprintf(stderr, "failed to get IServiceManager to poke hal services\n");
528 return;
529 }
530
531 auto listRet = sm->list([&](const auto &interfaces) {
532 for (size_t i = 0; i < interfaces.size(); i++) {
533 string fqInstanceName = interfaces[i];
534 string::size_type n = fqInstanceName.find("/");
535 if (n == std::string::npos || interfaces[i].size() == n+1)
536 continue;
537 hidl_string fqInterfaceName = fqInstanceName.substr(0, n);
538 hidl_string instanceName = fqInstanceName.substr(n+1, std::string::npos);
539 Return<sp<IBase>> interfaceRet = sm->get(fqInterfaceName, instanceName);
540 if (!interfaceRet.isOk()) {
541 // ignore
542 continue;
543 }
544
545 sp<IBase> interface = interfaceRet;
546 if (interface == nullptr) {
547 // ignore
548 continue;
549 }
550
551 auto notifyRet = interface->notifySyspropsChanged();
552 if (!notifyRet.isOk()) {
553 // ignore
554 }
555 }
556 });
557 if (!listRet.isOk()) {
558 // TODO(b/34242478) fix this when we determine the correct ACL
559 //fprintf(stderr, "failed to list services: %s\n", listRet.description().c_str());
560 }
561 }
562
563 // Set the trace tags that userland tracing uses, and poke the running
564 // processes to pick up the new value.
setTagsProperty(uint64_t tags)565 static bool setTagsProperty(uint64_t tags)
566 {
567 char buf[PROPERTY_VALUE_MAX];
568 snprintf(buf, sizeof(buf), "%#" PRIx64, tags);
569 if (property_set(k_traceTagsProperty, buf) < 0) {
570 fprintf(stderr, "error setting trace tags system property\n");
571 return false;
572 }
573 return true;
574 }
575
clearAppProperties()576 static void clearAppProperties()
577 {
578 char buf[PROPERTY_KEY_MAX];
579 for (int i = 0; i < MAX_PACKAGES; i++) {
580 snprintf(buf, sizeof(buf), k_traceAppsPropertyTemplate, i);
581 if (property_set(buf, "") < 0) {
582 fprintf(stderr, "failed to clear system property: %s\n", buf);
583 }
584 }
585 if (property_set(k_traceAppsNumberProperty, "") < 0) {
586 fprintf(stderr, "failed to clear system property: %s",
587 k_traceAppsNumberProperty);
588 }
589 }
590
591 // Set the system property that indicates which apps should perform
592 // application-level tracing.
setAppCmdlineProperty(char * cmdline)593 static bool setAppCmdlineProperty(char* cmdline)
594 {
595 char buf[PROPERTY_KEY_MAX];
596 int i = 0;
597 char* start = cmdline;
598 while (start != NULL) {
599 if (i == MAX_PACKAGES) {
600 fprintf(stderr, "error: only 16 packages could be traced at once\n");
601 clearAppProperties();
602 return false;
603 }
604 char* end = strchr(start, ',');
605 if (end != NULL) {
606 *end = '\0';
607 end++;
608 }
609 snprintf(buf, sizeof(buf), k_traceAppsPropertyTemplate, i);
610 if (property_set(buf, start) < 0) {
611 fprintf(stderr, "error setting trace app %d property to %s\n", i, buf);
612 clearAppProperties();
613 return false;
614 }
615 start = end;
616 i++;
617 }
618
619 snprintf(buf, sizeof(buf), "%d", i);
620 if (property_set(k_traceAppsNumberProperty, buf) < 0) {
621 fprintf(stderr, "error setting trace app number property to %s\n", buf);
622 clearAppProperties();
623 return false;
624 }
625 return true;
626 }
627
628 // Disable all /sys/ enable files.
disableKernelTraceEvents()629 static bool disableKernelTraceEvents() {
630 bool ok = true;
631 for (int i = 0; i < NELEM(k_categories); i++) {
632 const TracingCategory &c = k_categories[i];
633 for (int j = 0; j < MAX_SYS_FILES; j++) {
634 const char* path = c.sysfiles[j].path;
635 if (path != NULL && fileIsWritable(path)) {
636 ok &= setKernelOptionEnable(path, false);
637 }
638 }
639 }
640 return ok;
641 }
642
643 // Verify that the comma separated list of functions are being traced by the
644 // kernel.
verifyKernelTraceFuncs(const char * funcs)645 static bool verifyKernelTraceFuncs(const char* funcs)
646 {
647 std::string buf;
648 if (!android::base::ReadFileToString(g_traceFolder + k_ftraceFilterPath, &buf)) {
649 fprintf(stderr, "error opening %s: %s (%d)\n", k_ftraceFilterPath,
650 strerror(errno), errno);
651 return false;
652 }
653
654 String8 funcList = String8::format("\n%s",buf.c_str());
655
656 // Make sure that every function listed in funcs is in the list we just
657 // read from the kernel, except for wildcard inputs.
658 bool ok = true;
659 char* myFuncs = strdup(funcs);
660 char* func = strtok(myFuncs, ",");
661 while (func) {
662 if (!strchr(func, '*')) {
663 String8 fancyFunc = String8::format("\n%s\n", func);
664 bool found = funcList.find(fancyFunc.string(), 0) >= 0;
665 if (!found || func[0] == '\0') {
666 fprintf(stderr, "error: \"%s\" is not a valid kernel function "
667 "to trace.\n", func);
668 ok = false;
669 }
670 }
671 func = strtok(NULL, ",");
672 }
673 free(myFuncs);
674 return ok;
675 }
676
677 // Set the comma separated list of functions that the kernel is to trace.
setKernelTraceFuncs(const char * funcs)678 static bool setKernelTraceFuncs(const char* funcs)
679 {
680 bool ok = true;
681
682 if (funcs == NULL || funcs[0] == '\0') {
683 // Disable kernel function tracing.
684 if (fileIsWritable(k_currentTracerPath)) {
685 ok &= writeStr(k_currentTracerPath, "nop");
686 }
687 if (fileIsWritable(k_ftraceFilterPath)) {
688 ok &= truncateFile(k_ftraceFilterPath);
689 }
690 } else {
691 // Enable kernel function tracing.
692 ok &= writeStr(k_currentTracerPath, "function_graph");
693 ok &= setKernelOptionEnable(k_funcgraphAbsTimePath, true);
694 ok &= setKernelOptionEnable(k_funcgraphCpuPath, true);
695 ok &= setKernelOptionEnable(k_funcgraphProcPath, true);
696 ok &= setKernelOptionEnable(k_funcgraphFlatPath, true);
697
698 // Set the requested filter functions.
699 ok &= truncateFile(k_ftraceFilterPath);
700 char* myFuncs = strdup(funcs);
701 char* func = strtok(myFuncs, ",");
702 while (func) {
703 ok &= appendStr(k_ftraceFilterPath, func);
704 func = strtok(NULL, ",");
705 }
706 free(myFuncs);
707
708 // Verify that the set functions are being traced.
709 if (ok) {
710 ok &= verifyKernelTraceFuncs(funcs);
711 }
712 }
713
714 return ok;
715 }
716
setCategoryEnable(const char * name,bool enable)717 static bool setCategoryEnable(const char* name, bool enable)
718 {
719 for (int i = 0; i < NELEM(k_categories); i++) {
720 const TracingCategory& c = k_categories[i];
721 if (strcmp(name, c.name) == 0) {
722 if (isCategorySupported(c)) {
723 g_categoryEnables[i] = enable;
724 return true;
725 } else {
726 if (isCategorySupportedForRoot(c)) {
727 fprintf(stderr, "error: category \"%s\" requires root "
728 "privileges.\n", name);
729 } else {
730 fprintf(stderr, "error: category \"%s\" is not supported "
731 "on this device.\n", name);
732 }
733 return false;
734 }
735 }
736 }
737 fprintf(stderr, "error: unknown tracing category \"%s\"\n", name);
738 return false;
739 }
740
setCategoriesEnableFromFile(const char * categories_file)741 static bool setCategoriesEnableFromFile(const char* categories_file)
742 {
743 if (!categories_file) {
744 return true;
745 }
746 Tokenizer* tokenizer = NULL;
747 if (Tokenizer::open(String8(categories_file), &tokenizer) != NO_ERROR) {
748 return false;
749 }
750 bool ok = true;
751 while (!tokenizer->isEol()) {
752 String8 token = tokenizer->nextToken(" ");
753 if (token.isEmpty()) {
754 tokenizer->skipDelimiters(" ");
755 continue;
756 }
757 ok &= setCategoryEnable(token.string(), true);
758 }
759 delete tokenizer;
760 return ok;
761 }
762
763 // Set all the kernel tracing settings to the desired state for this trace
764 // capture.
setUpTrace()765 static bool setUpTrace()
766 {
767 bool ok = true;
768
769 // Set up the tracing options.
770 ok &= setCategoriesEnableFromFile(g_categoriesFile);
771 ok &= setTraceOverwriteEnable(g_traceOverwrite);
772 ok &= setTraceBufferSizeKB(g_traceBufferSizeKB);
773 // TODO: Re-enable after stabilization
774 //ok &= setCmdlineSize();
775 ok &= setClock();
776 ok &= setPrintTgidEnableIfPresent(true);
777 ok &= setKernelTraceFuncs(g_kernelTraceFuncs);
778
779 // Set up the tags property.
780 uint64_t tags = 0;
781 for (int i = 0; i < NELEM(k_categories); i++) {
782 if (g_categoryEnables[i]) {
783 const TracingCategory &c = k_categories[i];
784 tags |= c.tags;
785 }
786 }
787 ok &= setTagsProperty(tags);
788
789 bool coreServicesTagEnabled = false;
790 for (int i = 0; i < NELEM(k_categories); i++) {
791 if (strcmp(k_categories[i].name, k_coreServiceCategory) == 0) {
792 coreServicesTagEnabled = g_categoryEnables[i];
793 }
794 }
795
796 std::string packageList(g_debugAppCmdLine);
797 if (coreServicesTagEnabled) {
798 char value[PROPERTY_VALUE_MAX];
799 property_get(k_coreServicesProp, value, "");
800 if (!packageList.empty()) {
801 packageList += ",";
802 }
803 packageList += value;
804 }
805 ok &= setAppCmdlineProperty(&packageList[0]);
806 ok &= pokeBinderServices();
807 pokeHalServices();
808
809 // Disable all the sysfs enables. This is done as a separate loop from
810 // the enables to allow the same enable to exist in multiple categories.
811 ok &= disableKernelTraceEvents();
812
813 // Enable all the sysfs enables that are in an enabled category.
814 for (int i = 0; i < NELEM(k_categories); i++) {
815 if (g_categoryEnables[i]) {
816 const TracingCategory &c = k_categories[i];
817 for (int j = 0; j < MAX_SYS_FILES; j++) {
818 const char* path = c.sysfiles[j].path;
819 bool required = c.sysfiles[j].required == REQ;
820 if (path != NULL) {
821 if (fileIsWritable(path)) {
822 ok &= setKernelOptionEnable(path, true);
823 } else if (required) {
824 fprintf(stderr, "error writing file %s\n", path);
825 ok = false;
826 }
827 }
828 }
829 }
830 }
831
832 return ok;
833 }
834
835 // Reset all the kernel tracing settings to their default state.
cleanUpTrace()836 static void cleanUpTrace()
837 {
838 // Disable all tracing that we're able to.
839 disableKernelTraceEvents();
840
841 // Reset the system properties.
842 setTagsProperty(0);
843 clearAppProperties();
844 pokeBinderServices();
845
846 // Set the options back to their defaults.
847 setTraceOverwriteEnable(true);
848 setTraceBufferSizeKB(1);
849 setPrintTgidEnableIfPresent(false);
850 setKernelTraceFuncs(NULL);
851 }
852
853
854 // Enable tracing in the kernel.
startTrace()855 static bool startTrace()
856 {
857 return setTracingEnabled(true);
858 }
859
860 // Disable tracing in the kernel.
stopTrace()861 static void stopTrace()
862 {
863 setTracingEnabled(false);
864 }
865
866 // Read data from the tracing pipe and forward to stdout
streamTrace()867 static void streamTrace()
868 {
869 char trace_data[4096];
870 int traceFD = open((g_traceFolder + k_traceStreamPath).c_str(), O_RDWR);
871 if (traceFD == -1) {
872 fprintf(stderr, "error opening %s: %s (%d)\n", k_traceStreamPath,
873 strerror(errno), errno);
874 return;
875 }
876 while (!g_traceAborted) {
877 ssize_t bytes_read = read(traceFD, trace_data, 4096);
878 if (bytes_read > 0) {
879 write(STDOUT_FILENO, trace_data, bytes_read);
880 fflush(stdout);
881 } else {
882 if (!g_traceAborted) {
883 fprintf(stderr, "read returned %zd bytes err %d (%s)\n",
884 bytes_read, errno, strerror(errno));
885 }
886 break;
887 }
888 }
889 }
890
891 // Read the current kernel trace and write it to stdout.
dumpTrace(int outFd)892 static void dumpTrace(int outFd)
893 {
894 ALOGI("Dumping trace");
895 int traceFD = open((g_traceFolder + k_tracePath).c_str(), O_RDWR);
896 if (traceFD == -1) {
897 fprintf(stderr, "error opening %s: %s (%d)\n", k_tracePath,
898 strerror(errno), errno);
899 return;
900 }
901
902 if (g_compress) {
903 z_stream zs;
904 memset(&zs, 0, sizeof(zs));
905
906 int result = deflateInit(&zs, Z_DEFAULT_COMPRESSION);
907 if (result != Z_OK) {
908 fprintf(stderr, "error initializing zlib: %d\n", result);
909 close(traceFD);
910 return;
911 }
912
913 constexpr size_t bufSize = 64*1024;
914 std::unique_ptr<uint8_t> in(new uint8_t[bufSize]);
915 std::unique_ptr<uint8_t> out(new uint8_t[bufSize]);
916 if (!in || !out) {
917 fprintf(stderr, "couldn't allocate buffers\n");
918 close(traceFD);
919 return;
920 }
921
922 int flush = Z_NO_FLUSH;
923
924 zs.next_out = reinterpret_cast<Bytef*>(out.get());
925 zs.avail_out = bufSize;
926
927 do {
928
929 if (zs.avail_in == 0) {
930 // More input is needed.
931 result = read(traceFD, in.get(), bufSize);
932 if (result < 0) {
933 fprintf(stderr, "error reading trace: %s (%d)\n",
934 strerror(errno), errno);
935 result = Z_STREAM_END;
936 break;
937 } else if (result == 0) {
938 flush = Z_FINISH;
939 } else {
940 zs.next_in = reinterpret_cast<Bytef*>(in.get());
941 zs.avail_in = result;
942 }
943 }
944
945 if (zs.avail_out == 0) {
946 // Need to write the output.
947 result = write(outFd, out.get(), bufSize);
948 if ((size_t)result < bufSize) {
949 fprintf(stderr, "error writing deflated trace: %s (%d)\n",
950 strerror(errno), errno);
951 result = Z_STREAM_END; // skip deflate error message
952 zs.avail_out = bufSize; // skip the final write
953 break;
954 }
955 zs.next_out = reinterpret_cast<Bytef*>(out.get());
956 zs.avail_out = bufSize;
957 }
958
959 } while ((result = deflate(&zs, flush)) == Z_OK);
960
961 if (result != Z_STREAM_END) {
962 fprintf(stderr, "error deflating trace: %s\n", zs.msg);
963 }
964
965 if (zs.avail_out < bufSize) {
966 size_t bytes = bufSize - zs.avail_out;
967 result = write(outFd, out.get(), bytes);
968 if ((size_t)result < bytes) {
969 fprintf(stderr, "error writing deflated trace: %s (%d)\n",
970 strerror(errno), errno);
971 }
972 }
973
974 result = deflateEnd(&zs);
975 if (result != Z_OK) {
976 fprintf(stderr, "error cleaning up zlib: %d\n", result);
977 }
978 } else {
979 ssize_t sent = 0;
980 while ((sent = sendfile(outFd, traceFD, NULL, 64*1024*1024)) > 0);
981 if (sent == -1) {
982 fprintf(stderr, "error dumping trace: %s (%d)\n", strerror(errno),
983 errno);
984 }
985 }
986
987 close(traceFD);
988 }
989
handleSignal(int)990 static void handleSignal(int /*signo*/)
991 {
992 if (!g_nohup) {
993 g_traceAborted = true;
994 }
995 }
996
registerSigHandler()997 static void registerSigHandler()
998 {
999 struct sigaction sa;
1000 sigemptyset(&sa.sa_mask);
1001 sa.sa_flags = 0;
1002 sa.sa_handler = handleSignal;
1003 sigaction(SIGHUP, &sa, NULL);
1004 sigaction(SIGINT, &sa, NULL);
1005 sigaction(SIGQUIT, &sa, NULL);
1006 sigaction(SIGTERM, &sa, NULL);
1007 }
1008
listSupportedCategories()1009 static void listSupportedCategories()
1010 {
1011 for (int i = 0; i < NELEM(k_categories); i++) {
1012 const TracingCategory& c = k_categories[i];
1013 if (isCategorySupported(c)) {
1014 printf(" %10s - %s\n", c.name, c.longname);
1015 }
1016 }
1017 }
1018
1019 // Print the command usage help to stderr.
showHelp(const char * cmd)1020 static void showHelp(const char *cmd)
1021 {
1022 fprintf(stderr, "usage: %s [options] [categories...]\n", cmd);
1023 fprintf(stderr, "options include:\n"
1024 " -a appname enable app-level tracing for a comma "
1025 "separated list of cmdlines\n"
1026 " -b N use a trace buffer size of N KB\n"
1027 " -c trace into a circular buffer\n"
1028 " -f filename use the categories written in a file as space-separated\n"
1029 " values in a line\n"
1030 " -k fname,... trace the listed kernel functions\n"
1031 " -n ignore signals\n"
1032 " -s N sleep for N seconds before tracing [default 0]\n"
1033 " -t N trace for N seconds [default 5]\n"
1034 " -z compress the trace dump\n"
1035 " --async_start start circular trace and return immediately\n"
1036 " --async_dump dump the current contents of circular trace buffer\n"
1037 " --async_stop stop tracing and dump the current contents of circular\n"
1038 " trace buffer\n"
1039 " --stream stream trace to stdout as it enters the trace buffer\n"
1040 " Note: this can take significant CPU time, and is best\n"
1041 " used for measuring things that are not affected by\n"
1042 " CPU performance, like pagecache usage.\n"
1043 " --list_categories\n"
1044 " list the available tracing categories\n"
1045 " -o filename write the trace to the specified file instead\n"
1046 " of stdout.\n"
1047 );
1048 }
1049
findTraceFiles()1050 bool findTraceFiles()
1051 {
1052 static const std::string debugfs_path = "/sys/kernel/debug/tracing/";
1053 static const std::string tracefs_path = "/sys/kernel/tracing/";
1054 static const std::string trace_file = "trace_marker";
1055
1056 bool tracefs = access((tracefs_path + trace_file).c_str(), F_OK) != -1;
1057 bool debugfs = access((debugfs_path + trace_file).c_str(), F_OK) != -1;
1058
1059 if (!tracefs && !debugfs) {
1060 fprintf(stderr, "Error: Did not find trace folder\n");
1061 return false;
1062 }
1063
1064 if (tracefs) {
1065 g_traceFolder = tracefs_path;
1066 } else {
1067 g_traceFolder = debugfs_path;
1068 }
1069
1070 return true;
1071 }
1072
main(int argc,char ** argv)1073 int main(int argc, char **argv)
1074 {
1075 bool async = false;
1076 bool traceStart = true;
1077 bool traceStop = true;
1078 bool traceDump = true;
1079 bool traceStream = false;
1080
1081 if (argc == 2 && 0 == strcmp(argv[1], "--help")) {
1082 showHelp(argv[0]);
1083 exit(0);
1084 }
1085
1086 if (!findTraceFiles()) {
1087 fprintf(stderr, "No trace folder found\n");
1088 exit(-1);
1089 }
1090
1091 for (;;) {
1092 int ret;
1093 int option_index = 0;
1094 static struct option long_options[] = {
1095 {"async_start", no_argument, 0, 0 },
1096 {"async_stop", no_argument, 0, 0 },
1097 {"async_dump", no_argument, 0, 0 },
1098 {"list_categories", no_argument, 0, 0 },
1099 {"stream", no_argument, 0, 0 },
1100 { 0, 0, 0, 0 }
1101 };
1102
1103 ret = getopt_long(argc, argv, "a:b:cf:k:ns:t:zo:",
1104 long_options, &option_index);
1105
1106 if (ret < 0) {
1107 for (int i = optind; i < argc; i++) {
1108 if (!setCategoryEnable(argv[i], true)) {
1109 fprintf(stderr, "error enabling tracing category \"%s\"\n", argv[i]);
1110 exit(1);
1111 }
1112 }
1113 break;
1114 }
1115
1116 switch(ret) {
1117 case 'a':
1118 g_debugAppCmdLine = optarg;
1119 break;
1120
1121 case 'b':
1122 g_traceBufferSizeKB = atoi(optarg);
1123 break;
1124
1125 case 'c':
1126 g_traceOverwrite = true;
1127 break;
1128
1129 case 'f':
1130 g_categoriesFile = optarg;
1131 break;
1132
1133 case 'k':
1134 g_kernelTraceFuncs = optarg;
1135 break;
1136
1137 case 'n':
1138 g_nohup = true;
1139 break;
1140
1141 case 's':
1142 g_initialSleepSecs = atoi(optarg);
1143 break;
1144
1145 case 't':
1146 g_traceDurationSeconds = atoi(optarg);
1147 break;
1148
1149 case 'z':
1150 g_compress = true;
1151 break;
1152
1153 case 'o':
1154 g_outputFile = optarg;
1155 break;
1156
1157 case 0:
1158 if (!strcmp(long_options[option_index].name, "async_start")) {
1159 async = true;
1160 traceStop = false;
1161 traceDump = false;
1162 g_traceOverwrite = true;
1163 } else if (!strcmp(long_options[option_index].name, "async_stop")) {
1164 async = true;
1165 traceStart = false;
1166 } else if (!strcmp(long_options[option_index].name, "async_dump")) {
1167 async = true;
1168 traceStart = false;
1169 traceStop = false;
1170 } else if (!strcmp(long_options[option_index].name, "stream")) {
1171 traceStream = true;
1172 traceDump = false;
1173 } else if (!strcmp(long_options[option_index].name, "list_categories")) {
1174 listSupportedCategories();
1175 exit(0);
1176 }
1177 break;
1178
1179 default:
1180 fprintf(stderr, "\n");
1181 showHelp(argv[0]);
1182 exit(-1);
1183 break;
1184 }
1185 }
1186
1187 registerSigHandler();
1188
1189 if (g_initialSleepSecs > 0) {
1190 sleep(g_initialSleepSecs);
1191 }
1192
1193 bool ok = true;
1194 ok &= setUpTrace();
1195 ok &= startTrace();
1196
1197 if (ok && traceStart) {
1198 if (!traceStream) {
1199 printf("capturing trace...");
1200 fflush(stdout);
1201 }
1202
1203 // We clear the trace after starting it because tracing gets enabled for
1204 // each CPU individually in the kernel. Having the beginning of the trace
1205 // contain entries from only one CPU can cause "begin" entries without a
1206 // matching "end" entry to show up if a task gets migrated from one CPU to
1207 // another.
1208 ok = clearTrace();
1209
1210 writeClockSyncMarker();
1211 if (ok && !async && !traceStream) {
1212 // Sleep to allow the trace to be captured.
1213 struct timespec timeLeft;
1214 timeLeft.tv_sec = g_traceDurationSeconds;
1215 timeLeft.tv_nsec = 0;
1216 do {
1217 if (g_traceAborted) {
1218 break;
1219 }
1220 } while (nanosleep(&timeLeft, &timeLeft) == -1 && errno == EINTR);
1221 }
1222
1223 if (traceStream) {
1224 streamTrace();
1225 }
1226 }
1227
1228 // Stop the trace and restore the default settings.
1229 if (traceStop)
1230 stopTrace();
1231
1232 if (ok && traceDump) {
1233 if (!g_traceAborted) {
1234 printf(" done\n");
1235 fflush(stdout);
1236 int outFd = STDOUT_FILENO;
1237 if (g_outputFile) {
1238 outFd = open(g_outputFile, O_WRONLY | O_CREAT | O_TRUNC, 0644);
1239 }
1240 if (outFd == -1) {
1241 printf("Failed to open '%s', err=%d", g_outputFile, errno);
1242 } else {
1243 dprintf(outFd, "TRACE:\n");
1244 dumpTrace(outFd);
1245 if (g_outputFile) {
1246 close(outFd);
1247 }
1248 }
1249 } else {
1250 printf("\ntrace aborted.\n");
1251 fflush(stdout);
1252 }
1253 clearTrace();
1254 } else if (!ok) {
1255 fprintf(stderr, "unable to start tracing\n");
1256 }
1257
1258 // Reset the trace buffer size to 1.
1259 if (traceStop)
1260 cleanUpTrace();
1261
1262 return g_traceAborted ? 1 : 0;
1263 }
1264