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