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