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