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