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