atrace.cpp revision b2a89e3155969e5bc9653966069d6dbabdd3f623
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 <signal.h> 21#include <stdarg.h> 22#include <stdbool.h> 23#include <stdio.h> 24#include <stdlib.h> 25#include <sys/sendfile.h> 26#include <time.h> 27#include <zlib.h> 28 29#include <binder/IBinder.h> 30#include <binder/IServiceManager.h> 31#include <binder/Parcel.h> 32 33#include <cutils/properties.h> 34 35#include <utils/String8.h> 36#include <utils/Trace.h> 37 38using namespace android; 39 40#define NELEM(x) ((int) (sizeof(x) / sizeof((x)[0]))) 41 42enum { MAX_SYS_FILES = 8 }; 43 44const char* k_traceTagsProperty = "debug.atrace.tags.enableflags"; 45 46typedef enum { OPT, REQ } requiredness ; 47 48struct TracingCategory { 49 // The name identifying the category. 50 const char* name; 51 52 // A longer description of the category. 53 const char* longname; 54 55 // The userland tracing tags that the category enables. 56 uint64_t tags; 57 58 // The fname==NULL terminated list of /sys/ files that the category 59 // enables. 60 struct { 61 // Whether the file must be writable in order to enable the tracing 62 // category. 63 requiredness required; 64 65 // The path to the enable file. 66 const char* path; 67 } sysfiles[MAX_SYS_FILES]; 68}; 69 70/* Tracing categories */ 71static const TracingCategory k_categories[] = { 72 { "gfx", "Graphics", ATRACE_TAG_GRAPHICS, { } }, 73 { "input", "Input", ATRACE_TAG_INPUT, { } }, 74 { "view", "View System", ATRACE_TAG_VIEW, { } }, 75 { "webview", "WebView", ATRACE_TAG_WEBVIEW, { } }, 76 { "wm", "Window Manager", ATRACE_TAG_WINDOW_MANAGER, { } }, 77 { "am", "Activity Manager", ATRACE_TAG_ACTIVITY_MANAGER, { } }, 78 { "audio", "Audio", ATRACE_TAG_AUDIO, { } }, 79 { "video", "Video", ATRACE_TAG_VIDEO, { } }, 80 { "camera", "Camera", ATRACE_TAG_CAMERA, { } }, 81 { "hal", "Hardware Modules", ATRACE_TAG_HAL, { } }, 82 { "sched", "CPU Scheduling", 0, { 83 { REQ, "/sys/kernel/debug/tracing/events/sched/sched_switch/enable" }, 84 { REQ, "/sys/kernel/debug/tracing/events/sched/sched_wakeup/enable" }, 85 } }, 86 { "freq", "CPU Frequency", 0, { 87 { REQ, "/sys/kernel/debug/tracing/events/power/cpu_frequency/enable" }, 88 { OPT, "/sys/kernel/debug/tracing/events/power/clock_set_rate/enable" }, 89 } }, 90 { "membus", "Memory Bus Utilization", 0, { 91 { REQ, "/sys/kernel/debug/tracing/events/memory_bus/enable" }, 92 } }, 93 { "idle", "CPU Idle", 0, { 94 { REQ, "/sys/kernel/debug/tracing/events/power/cpu_idle/enable" }, 95 } }, 96 { "disk", "Disk I/O", 0, { 97 { REQ, "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable" }, 98 { REQ, "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_exit/enable" }, 99 { REQ, "/sys/kernel/debug/tracing/events/block/block_rq_issue/enable" }, 100 { REQ, "/sys/kernel/debug/tracing/events/block/block_rq_complete/enable" }, 101 } }, 102 { "load", "CPU Load", 0, { 103 { REQ, "/sys/kernel/debug/tracing/events/cpufreq_interactive/enable" }, 104 } }, 105 { "sync", "Synchronization", 0, { 106 { REQ, "/sys/kernel/debug/tracing/events/sync/enable" }, 107 } }, 108 { "workq", "Kernel Workqueues", 0, { 109 { REQ, "/sys/kernel/debug/tracing/events/workqueue/enable" }, 110 } }, 111}; 112 113/* Command line options */ 114static int g_traceDurationSeconds = 5; 115static bool g_traceOverwrite = false; 116static int g_traceBufferSizeKB = 2048; 117static bool g_compress = false; 118static bool g_nohup = false; 119static int g_initialSleepSecs = 0; 120 121/* Global state */ 122static bool g_traceAborted = false; 123static bool g_categoryEnables[NELEM(k_categories)] = {}; 124 125/* Sys file paths */ 126static const char* k_traceClockPath = 127 "/sys/kernel/debug/tracing/trace_clock"; 128 129static const char* k_traceBufferSizePath = 130 "/sys/kernel/debug/tracing/buffer_size_kb"; 131 132static const char* k_tracingOverwriteEnablePath = 133 "/sys/kernel/debug/tracing/options/overwrite"; 134 135static const char* k_tracingOnPath = 136 "/sys/kernel/debug/tracing/tracing_on"; 137 138static const char* k_tracePath = 139 "/sys/kernel/debug/tracing/trace"; 140 141// Check whether a file exists. 142static bool fileExists(const char* filename) { 143 return access(filename, F_OK) != -1; 144} 145 146// Check whether a file is writable. 147static bool fileIsWritable(const char* filename) { 148 return access(filename, W_OK) != -1; 149} 150 151// Write a string to a file, returning true if the write was successful. 152static bool writeStr(const char* filename, const char* str) 153{ 154 int fd = open(filename, O_WRONLY); 155 if (fd == -1) { 156 fprintf(stderr, "error opening %s: %s (%d)\n", filename, 157 strerror(errno), errno); 158 return false; 159 } 160 161 bool ok = true; 162 ssize_t len = strlen(str); 163 if (write(fd, str, len) != len) { 164 fprintf(stderr, "error writing to %s: %s (%d)\n", filename, 165 strerror(errno), errno); 166 ok = false; 167 } 168 169 close(fd); 170 171 return ok; 172} 173 174// Enable or disable a kernel option by writing a "1" or a "0" into a /sys 175// file. 176static bool setKernelOptionEnable(const char* filename, bool enable) 177{ 178 return writeStr(filename, enable ? "1" : "0"); 179} 180 181// Check whether the category is supported on the device with the current 182// rootness. A category is supported only if all its required /sys/ files are 183// writable and if enabling the category will enable one or more tracing tags 184// or /sys/ files. 185static bool isCategorySupported(const TracingCategory& category) 186{ 187 bool ok = category.tags != 0; 188 for (int i = 0; i < MAX_SYS_FILES; i++) { 189 const char* path = category.sysfiles[i].path; 190 bool req = category.sysfiles[i].required == REQ; 191 if (path != NULL) { 192 if (req) { 193 if (!fileIsWritable(path)) { 194 return false; 195 } else { 196 ok = true; 197 } 198 } else { 199 ok |= fileIsWritable(path); 200 } 201 } 202 } 203 return ok; 204} 205 206// Check whether the category would be supported on the device if the user 207// were root. This function assumes that root is able to write to any file 208// that exists. It performs the same logic as isCategorySupported, but it 209// uses file existance rather than writability in the /sys/ file checks. 210static bool isCategorySupportedForRoot(const TracingCategory& category) 211{ 212 bool ok = category.tags != 0; 213 for (int i = 0; i < MAX_SYS_FILES; i++) { 214 const char* path = category.sysfiles[i].path; 215 bool req = category.sysfiles[i].required == REQ; 216 if (path != NULL) { 217 if (req) { 218 if (!fileExists(path)) { 219 return false; 220 } else { 221 ok = true; 222 } 223 } else { 224 ok |= fileExists(path); 225 } 226 } 227 } 228 return ok; 229} 230 231// Enable or disable overwriting of the kernel trace buffers. Disabling this 232// will cause tracing to stop once the trace buffers have filled up. 233static bool setTraceOverwriteEnable(bool enable) 234{ 235 return setKernelOptionEnable(k_tracingOverwriteEnablePath, enable); 236} 237 238// Enable or disable kernel tracing. 239static bool setTracingEnabled(bool enable) 240{ 241 return setKernelOptionEnable(k_tracingOnPath, enable); 242} 243 244// Clear the contents of the kernel trace. 245static bool clearTrace() 246{ 247 int traceFD = creat(k_tracePath, 0); 248 if (traceFD == -1) { 249 fprintf(stderr, "error truncating %s: %s (%d)\n", k_tracePath, 250 strerror(errno), errno); 251 return false; 252 } 253 254 close(traceFD); 255 256 return true; 257} 258 259// Set the size of the kernel's trace buffer in kilobytes. 260static bool setTraceBufferSizeKB(int size) 261{ 262 char str[32] = "1"; 263 int len; 264 if (size < 1) { 265 size = 1; 266 } 267 snprintf(str, 32, "%d", size); 268 return writeStr(k_traceBufferSizePath, str); 269} 270 271// Enable or disable the kernel's use of the global clock. Disabling the global 272// clock will result in the kernel using a per-CPU local clock. 273static bool setGlobalClockEnable(bool enable) 274{ 275 return writeStr(k_traceClockPath, enable ? "global" : "local"); 276} 277 278// Poke all the binder-enabled processes in the system to get them to re-read 279// their system properties. 280static bool pokeBinderServices() 281{ 282 sp<IServiceManager> sm = defaultServiceManager(); 283 Vector<String16> services = sm->listServices(); 284 for (size_t i = 0; i < services.size(); i++) { 285 sp<IBinder> obj = sm->checkService(services[i]); 286 if (obj != NULL) { 287 Parcel data; 288 if (obj->transact(IBinder::SYSPROPS_TRANSACTION, data, 289 NULL, 0) != OK) { 290 if (false) { 291 // XXX: For some reason this fails on tablets trying to 292 // poke the "phone" service. It's not clear whether some 293 // are expected to fail. 294 String8 svc(services[i]); 295 fprintf(stderr, "error poking binder service %s\n", 296 svc.string()); 297 return false; 298 } 299 } 300 } 301 } 302 return true; 303} 304 305// Set the trace tags that userland tracing uses, and poke the running 306// processes to pick up the new value. 307static bool setTagsProperty(uint64_t tags) 308{ 309 char buf[64]; 310 snprintf(buf, 64, "%#llx", tags); 311 if (property_set(k_traceTagsProperty, buf) < 0) { 312 fprintf(stderr, "error setting trace tags system property\n"); 313 return false; 314 } 315 return pokeBinderServices(); 316} 317 318// Disable all /sys/ enable files. 319static bool disableKernelTraceEvents() { 320 bool ok = true; 321 for (int i = 0; i < NELEM(k_categories); i++) { 322 const TracingCategory &c = k_categories[i]; 323 for (int j = 0; j < MAX_SYS_FILES; j++) { 324 const char* path = c.sysfiles[j].path; 325 if (path != NULL && fileIsWritable(path)) { 326 ok &= setKernelOptionEnable(path, false); 327 } 328 } 329 } 330 return ok; 331} 332 333// Enable tracing in the kernel. 334static bool startTrace() 335{ 336 bool ok = true; 337 338 // Set up the tracing options. 339 ok &= setTraceOverwriteEnable(g_traceOverwrite); 340 ok &= setTraceBufferSizeKB(g_traceBufferSizeKB); 341 ok &= setGlobalClockEnable(true); 342 343 // Set up the tags property. 344 uint64_t tags = 0; 345 for (int i = 0; i < NELEM(k_categories); i++) { 346 if (g_categoryEnables[i]) { 347 const TracingCategory &c = k_categories[i]; 348 tags |= c.tags; 349 } 350 } 351 ok &= setTagsProperty(tags); 352 353 // Disable all the sysfs enables. This is done as a separate loop from 354 // the enables to allow the same enable to exist in multiple categories. 355 ok &= disableKernelTraceEvents(); 356 357 // Enable all the sysfs enables that are in an enabled category. 358 for (int i = 0; i < NELEM(k_categories); i++) { 359 if (g_categoryEnables[i]) { 360 const TracingCategory &c = k_categories[i]; 361 for (int j = 0; j < MAX_SYS_FILES; j++) { 362 const char* path = c.sysfiles[j].path; 363 bool required = c.sysfiles[j].required == REQ; 364 if (path != NULL) { 365 if (fileIsWritable(path)) { 366 ok &= setKernelOptionEnable(path, true); 367 } else if (required) { 368 fprintf(stderr, "error writing file %s\n", path); 369 ok = false; 370 } 371 } 372 } 373 } 374 } 375 376 // Enable tracing. 377 ok &= setTracingEnabled(true); 378 379 return ok; 380} 381 382// Disable tracing in the kernel. 383static void stopTrace() 384{ 385 // Disable tracing. 386 setTracingEnabled(false); 387 388 // Disable all tracing that we're able to. 389 disableKernelTraceEvents(); 390 391 // Disable all the trace tags. 392 setTagsProperty(0); 393 394 // Set the options back to their defaults. 395 setTraceOverwriteEnable(true); 396 setGlobalClockEnable(false); 397 398 // Note that we can't reset the trace buffer size here because that would 399 // clear the trace before we've read it. 400} 401 402// Read the current kernel trace and write it to stdout. 403static void dumpTrace() 404{ 405 int traceFD = open(k_tracePath, O_RDWR); 406 if (traceFD == -1) { 407 fprintf(stderr, "error opening %s: %s (%d)\n", k_tracePath, 408 strerror(errno), errno); 409 return; 410 } 411 412 if (g_compress) { 413 z_stream zs; 414 uint8_t *in, *out; 415 int result, flush; 416 417 bzero(&zs, sizeof(zs)); 418 result = deflateInit(&zs, Z_DEFAULT_COMPRESSION); 419 if (result != Z_OK) { 420 fprintf(stderr, "error initializing zlib: %d\n", result); 421 close(traceFD); 422 return; 423 } 424 425 const size_t bufSize = 64*1024; 426 in = (uint8_t*)malloc(bufSize); 427 out = (uint8_t*)malloc(bufSize); 428 flush = Z_NO_FLUSH; 429 430 zs.next_out = out; 431 zs.avail_out = bufSize; 432 433 do { 434 435 if (zs.avail_in == 0) { 436 // More input is needed. 437 result = read(traceFD, in, bufSize); 438 if (result < 0) { 439 fprintf(stderr, "error reading trace: %s (%d)\n", 440 strerror(errno), errno); 441 result = Z_STREAM_END; 442 break; 443 } else if (result == 0) { 444 flush = Z_FINISH; 445 } else { 446 zs.next_in = in; 447 zs.avail_in = result; 448 } 449 } 450 451 if (zs.avail_out == 0) { 452 // Need to write the output. 453 result = write(STDOUT_FILENO, out, bufSize); 454 if ((size_t)result < bufSize) { 455 fprintf(stderr, "error writing deflated trace: %s (%d)\n", 456 strerror(errno), errno); 457 result = Z_STREAM_END; // skip deflate error message 458 zs.avail_out = bufSize; // skip the final write 459 break; 460 } 461 zs.next_out = out; 462 zs.avail_out = bufSize; 463 } 464 465 } while ((result = deflate(&zs, flush)) == Z_OK); 466 467 if (result != Z_STREAM_END) { 468 fprintf(stderr, "error deflating trace: %s\n", zs.msg); 469 } 470 471 if (zs.avail_out < bufSize) { 472 size_t bytes = bufSize - zs.avail_out; 473 result = write(STDOUT_FILENO, out, bytes); 474 if ((size_t)result < bytes) { 475 fprintf(stderr, "error writing deflated trace: %s (%d)\n", 476 strerror(errno), errno); 477 } 478 } 479 480 result = deflateEnd(&zs); 481 if (result != Z_OK) { 482 fprintf(stderr, "error cleaning up zlib: %d\n", result); 483 } 484 485 free(in); 486 free(out); 487 } else { 488 ssize_t sent = 0; 489 while ((sent = sendfile(STDOUT_FILENO, traceFD, NULL, 64*1024*1024)) > 0); 490 if (sent == -1) { 491 fprintf(stderr, "error dumping trace: %s (%d)\n", strerror(errno), 492 errno); 493 } 494 } 495 496 close(traceFD); 497} 498 499static void handleSignal(int signo) 500{ 501 if (!g_nohup) { 502 g_traceAborted = true; 503 } 504} 505 506static void registerSigHandler() 507{ 508 struct sigaction sa; 509 sigemptyset(&sa.sa_mask); 510 sa.sa_flags = 0; 511 sa.sa_handler = handleSignal; 512 sigaction(SIGHUP, &sa, NULL); 513 sigaction(SIGINT, &sa, NULL); 514 sigaction(SIGQUIT, &sa, NULL); 515 sigaction(SIGTERM, &sa, NULL); 516} 517 518static bool setCategoryEnable(const char* name, bool enable) 519{ 520 for (int i = 0; i < NELEM(k_categories); i++) { 521 const TracingCategory& c = k_categories[i]; 522 if (strcmp(name, c.name) == 0) { 523 if (isCategorySupported(c)) { 524 g_categoryEnables[i] = enable; 525 return true; 526 } else { 527 if (isCategorySupportedForRoot(c)) { 528 fprintf(stderr, "error: category \"%s\" requires root " 529 "privileges.\n", name); 530 } else { 531 fprintf(stderr, "error: category \"%s\" is not supported " 532 "on this device.\n", name); 533 } 534 return false; 535 } 536 } 537 } 538 fprintf(stderr, "error: unknown tracing category \"%s\"\n", name); 539 return false; 540} 541 542static void listSupportedCategories() 543{ 544 for (int i = 0; i < NELEM(k_categories); i++) { 545 const TracingCategory& c = k_categories[i]; 546 if (isCategorySupported(c)) { 547 printf(" %10s - %s\n", c.name, c.longname); 548 } 549 } 550} 551 552// Print the command usage help to stderr. 553static void showHelp(const char *cmd) 554{ 555 fprintf(stderr, "usage: %s [options] [categories...]\n", cmd); 556 fprintf(stderr, "options include:\n" 557 " -b N use a trace buffer size of N KB\n" 558 " -c trace into a circular buffer\n" 559 " -n ignore signals\n" 560 " -s N sleep for N seconds before tracing [default 0]\n" 561 " -t N trace for N seconds [defualt 5]\n" 562 " -z compress the trace dump\n" 563 " --async_start start circular trace and return immediatly\n" 564 " --async_dump dump the current contents of circular trace buffer\n" 565 " --async_stop stop tracing and dump the current contents of circular\n" 566 " trace buffer\n" 567 " --list_categories\n" 568 " list the available tracing categories\n" 569 ); 570} 571 572int main(int argc, char **argv) 573{ 574 bool async = false; 575 bool traceStart = true; 576 bool traceStop = true; 577 bool traceDump = true; 578 579 if (argc == 2 && 0 == strcmp(argv[1], "--help")) { 580 showHelp(argv[0]); 581 exit(0); 582 } 583 584 for (;;) { 585 int ret; 586 int option_index = 0; 587 static struct option long_options[] = { 588 {"async_start", no_argument, 0, 0 }, 589 {"async_stop", no_argument, 0, 0 }, 590 {"async_dump", no_argument, 0, 0 }, 591 {"list_categories", no_argument, 0, 0 }, 592 { 0, 0, 0, 0 } 593 }; 594 595 ret = getopt_long(argc, argv, "b:cns:t:z", 596 long_options, &option_index); 597 598 if (ret < 0) { 599 for (int i = optind; i < argc; i++) { 600 if (!setCategoryEnable(argv[i], true)) { 601 fprintf(stderr, "error enabling tracing category \"%s\"\n", argv[i]); 602 exit(1); 603 } 604 } 605 break; 606 } 607 608 switch(ret) { 609 case 'b': 610 g_traceBufferSizeKB = atoi(optarg); 611 break; 612 613 case 'c': 614 g_traceOverwrite = true; 615 break; 616 617 case 'n': 618 g_nohup = true; 619 break; 620 621 case 's': 622 g_initialSleepSecs = atoi(optarg); 623 break; 624 625 case 't': 626 g_traceDurationSeconds = atoi(optarg); 627 break; 628 629 case 'z': 630 g_compress = true; 631 break; 632 633 case 0: 634 if (!strcmp(long_options[option_index].name, "async_start")) { 635 async = true; 636 traceStop = false; 637 traceDump = false; 638 g_traceOverwrite = true; 639 } else if (!strcmp(long_options[option_index].name, "async_stop")) { 640 async = true; 641 traceStop = false; 642 } else if (!strcmp(long_options[option_index].name, "async_dump")) { 643 async = true; 644 traceStart = false; 645 traceStop = false; 646 } else if (!strcmp(long_options[option_index].name, "list_categories")) { 647 listSupportedCategories(); 648 exit(0); 649 } 650 break; 651 652 default: 653 fprintf(stderr, "\n"); 654 showHelp(argv[0]); 655 exit(-1); 656 break; 657 } 658 } 659 660 registerSigHandler(); 661 662 if (g_initialSleepSecs > 0) { 663 sleep(g_initialSleepSecs); 664 } 665 666 bool ok = startTrace(); 667 668 if (ok && traceStart) { 669 printf("capturing trace..."); 670 fflush(stdout); 671 672 // We clear the trace after starting it because tracing gets enabled for 673 // each CPU individually in the kernel. Having the beginning of the trace 674 // contain entries from only one CPU can cause "begin" entries without a 675 // matching "end" entry to show up if a task gets migrated from one CPU to 676 // another. 677 ok = clearTrace(); 678 679 if (ok && !async) { 680 // Sleep to allow the trace to be captured. 681 struct timespec timeLeft; 682 timeLeft.tv_sec = g_traceDurationSeconds; 683 timeLeft.tv_nsec = 0; 684 do { 685 if (g_traceAborted) { 686 break; 687 } 688 } while (nanosleep(&timeLeft, &timeLeft) == -1 && errno == EINTR); 689 } 690 } 691 692 // Stop the trace and restore the default settings. 693 if (traceStop) 694 stopTrace(); 695 696 if (ok && traceDump) { 697 if (!g_traceAborted) { 698 printf(" done\nTRACE:\n"); 699 fflush(stdout); 700 dumpTrace(); 701 } else { 702 printf("\ntrace aborted.\n"); 703 fflush(stdout); 704 } 705 clearTrace(); 706 } else if (!ok) { 707 fprintf(stderr, "unable to start tracing\n"); 708 } 709 710 // Reset the trace buffer size to 1. 711 if (traceStop) 712 setTraceBufferSizeKB(1); 713 714 return g_traceAborted ? 1 : 0; 715} 716