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