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