atrace.c revision 24505a5826d7c5cf89f3da85058befd671a73444
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 <signal.h> 20#include <stdarg.h> 21#include <stdbool.h> 22#include <stdio.h> 23#include <stdlib.h> 24#include <sys/sendfile.h> 25#include <time.h> 26#include <zlib.h> 27 28#define NELEM(x) ((int) (sizeof(x) / sizeof((x)[0]))) 29 30/* Command line options */ 31static int g_traceDurationSeconds = 5; 32static bool g_traceSchedSwitch = false; 33static bool g_traceFrequency = false; 34static bool g_traceBusUtilization = false; 35static bool g_traceCpuIdle = false; 36static bool g_traceDisk = false; 37static bool g_traceGovernorLoad = false; 38static bool g_traceWorkqueue = false; 39static bool g_traceOverwrite = false; 40static int g_traceBufferSizeKB = 2048; 41static bool g_compress = false; 42 43/* Global state */ 44static bool g_traceAborted = false; 45 46/* Sys file paths */ 47static const char* k_traceClockPath = 48 "/sys/kernel/debug/tracing/trace_clock"; 49 50static const char* k_traceBufferSizePath = 51 "/sys/kernel/debug/tracing/buffer_size_kb"; 52 53static const char* k_tracingOverwriteEnablePath = 54 "/sys/kernel/debug/tracing/options/overwrite"; 55 56static const char* k_schedSwitchEnablePath = 57 "/sys/kernel/debug/tracing/events/sched/sched_switch/enable"; 58 59static const char* k_schedWakeupEnablePath = 60 "/sys/kernel/debug/tracing/events/sched/sched_wakeup/enable"; 61 62static const char* k_memoryBusEnablePath = 63 "/sys/kernel/debug/tracing/events/memory_bus/enable"; 64 65static const char* k_cpuFreqEnablePath = 66 "/sys/kernel/debug/tracing/events/power/cpu_frequency/enable"; 67 68static const char *k_clockSetRateEnablePath = 69 "/sys/kernel/debug/tracing/events/power/clock_set_rate/enable"; 70 71static const char* k_cpuIdleEnablePath = 72 "/sys/kernel/debug/tracing/events/power/cpu_idle/enable"; 73 74static const char* k_governorLoadEnablePath = 75 "/sys/kernel/debug/tracing/events/cpufreq_interactive/enable"; 76 77static const char* k_workqueueEnablePath = 78 "/sys/kernel/debug/tracing/events/workqueue/enable"; 79 80static const char* k_diskEnablePaths[] = { 81 "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable", 82 "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_exit/enable", 83 "/sys/kernel/debug/tracing/events/block/block_rq_issue/enable", 84 "/sys/kernel/debug/tracing/events/block/block_rq_complete/enable", 85}; 86 87static const char* k_tracingOnPath = 88 "/sys/kernel/debug/tracing/tracing_on"; 89 90static const char* k_tracePath = 91 "/sys/kernel/debug/tracing/trace"; 92 93static const char* k_traceMarkerPath = 94 "/sys/kernel/debug/tracing/trace_marker"; 95 96// Check whether a file exists. 97static bool fileExists(const char* filename) { 98 return access(filename, F_OK) != -1; 99} 100 101// Write a string to a file, returning true if the write was successful. 102bool writeStr(const char* filename, const char* str) 103{ 104 int fd = open(filename, O_WRONLY); 105 if (fd == -1) { 106 fprintf(stderr, "error opening %s: %s (%d)\n", filename, 107 strerror(errno), errno); 108 return false; 109 } 110 111 bool ok = true; 112 ssize_t len = strlen(str); 113 if (write(fd, str, len) != len) { 114 fprintf(stderr, "error writing to %s: %s (%d)\n", filename, 115 strerror(errno), errno); 116 ok = false; 117 } 118 119 close(fd); 120 121 return ok; 122} 123 124// Enable or disable a kernel option by writing a "1" or a "0" into a /sys file. 125static bool setKernelOptionEnable(const char* filename, bool enable) 126{ 127 return writeStr(filename, enable ? "1" : "0"); 128} 129 130// Enable or disable a collection of kernel options by writing a "1" or a "0" into each /sys file. 131static bool setMultipleKernelOptionsEnable(const char** filenames, size_t count, bool enable) 132{ 133 bool result = true; 134 for (size_t i = 0; i < count; i++) { 135 result &= setKernelOptionEnable(filenames[i], enable); 136 } 137 return result; 138} 139 140// Enable or disable overwriting of the kernel trace buffers. Disabling this 141// will cause tracing to stop once the trace buffers have filled up. 142static bool setTraceOverwriteEnable(bool enable) 143{ 144 return setKernelOptionEnable(k_tracingOverwriteEnablePath, enable); 145} 146 147// Enable or disable tracing of the kernel scheduler switching. 148static bool setSchedSwitchTracingEnable(bool enable) 149{ 150 bool ok = true; 151 ok &= setKernelOptionEnable(k_schedSwitchEnablePath, enable); 152 ok &= setKernelOptionEnable(k_schedWakeupEnablePath, enable); 153 return ok; 154} 155 156// Enable or disable tracing of the Bus utilization. 157static bool setBusUtilizationTracingEnable(bool enable) 158{ 159 bool ok = true, oneSet = false; 160 // these can be platform specific so make sure that at least 161 // one succeeds. 162 if (fileExists(k_memoryBusEnablePath)) { 163 ok &= setKernelOptionEnable(k_memoryBusEnablePath, enable); 164 oneSet |= ok; 165 } 166 return ok && (oneSet || !enable); 167} 168 169// Enable or disable tracing of the CPU clock frequency. 170static bool setFrequencyTracingEnable(bool enable) 171{ 172 bool ok = true; 173 ok &= setKernelOptionEnable(k_cpuFreqEnablePath, enable); 174 if (fileExists(k_clockSetRateEnablePath)) { 175 ok &= setKernelOptionEnable(k_clockSetRateEnablePath, enable); 176 } 177 return ok; 178} 179 180// Enable or disable tracing of CPU idle events. 181static bool setCpuIdleTracingEnable(bool enable) 182{ 183 return setKernelOptionEnable(k_cpuIdleEnablePath, enable); 184} 185 186// Enable or disable tracing of the interactive CPU frequency governor's idea of 187// the CPU load. 188static bool setGovernorLoadTracingEnable(bool enable) 189{ 190 bool ok = true; 191 if (fileExists(k_governorLoadEnablePath) || enable) { 192 ok &= setKernelOptionEnable(k_governorLoadEnablePath, enable); 193 } 194 return ok; 195} 196 197// Enable or disable tracing of the kernel workqueues. 198static bool setWorkqueueTracingEnabled(bool enable) 199{ 200 return setKernelOptionEnable(k_workqueueEnablePath, enable); 201} 202 203// Enable or disable tracing of disk I/O. 204static bool setDiskTracingEnabled(bool enable) 205{ 206 return setMultipleKernelOptionsEnable(k_diskEnablePaths, NELEM(k_diskEnablePaths), enable); 207} 208 209// Enable or disable kernel tracing. 210static bool setTracingEnabled(bool enable) 211{ 212 return setKernelOptionEnable(k_tracingOnPath, enable); 213} 214 215// Clear the contents of the kernel trace. 216static bool clearTrace() 217{ 218 int traceFD = creat(k_tracePath, 0); 219 if (traceFD == -1) { 220 fprintf(stderr, "error truncating %s: %s (%d)\n", k_tracePath, 221 strerror(errno), errno); 222 return false; 223 } 224 225 close(traceFD); 226 227 return true; 228} 229 230// Set the size of the kernel's trace buffer in kilobytes. 231static bool setTraceBufferSizeKB(int size) 232{ 233 char str[32] = "1"; 234 int len; 235 if (size < 1) { 236 size = 1; 237 } 238 snprintf(str, 32, "%d", size); 239 return writeStr(k_traceBufferSizePath, str); 240} 241 242// Enable or disable the kernel's use of the global clock. Disabling the global 243// clock will result in the kernel using a per-CPU local clock. 244static bool setGlobalClockEnable(bool enable) 245{ 246 return writeStr(k_traceClockPath, enable ? "global" : "local"); 247} 248 249// Enable tracing in the kernel. 250static bool startTrace(bool isRoot) 251{ 252 bool ok = true; 253 254 // Set up the tracing options that don't require root. 255 ok &= setTraceOverwriteEnable(g_traceOverwrite); 256 ok &= setSchedSwitchTracingEnable(g_traceSchedSwitch); 257 ok &= setFrequencyTracingEnable(g_traceFrequency); 258 ok &= setCpuIdleTracingEnable(g_traceCpuIdle); 259 ok &= setGovernorLoadTracingEnable(g_traceGovernorLoad); 260 ok &= setTraceBufferSizeKB(g_traceBufferSizeKB); 261 ok &= setGlobalClockEnable(true); 262 263 // Set up the tracing options that do require root. The options that 264 // require root should have errored out earlier if we're not running as 265 // root. 266 if (isRoot) { 267 ok &= setBusUtilizationTracingEnable(g_traceBusUtilization); 268 ok &= setWorkqueueTracingEnabled(g_traceWorkqueue); 269 ok &= setDiskTracingEnabled(g_traceDisk); 270 } 271 272 // Enable tracing. 273 ok &= setTracingEnabled(true); 274 275 if (!ok) { 276 fprintf(stderr, "error: unable to start trace\n"); 277 } 278 279 return ok; 280} 281 282// Disable tracing in the kernel. 283static void stopTrace(bool isRoot) 284{ 285 // Disable tracing. 286 setTracingEnabled(false); 287 288 // Set the options back to their defaults. 289 setTraceOverwriteEnable(true); 290 setSchedSwitchTracingEnable(false); 291 setFrequencyTracingEnable(false); 292 setGovernorLoadTracingEnable(false); 293 setGlobalClockEnable(false); 294 295 if (isRoot) { 296 setBusUtilizationTracingEnable(false); 297 setWorkqueueTracingEnabled(false); 298 setDiskTracingEnabled(false); 299 } 300 301 // Note that we can't reset the trace buffer size here because that would 302 // clear the trace before we've read it. 303} 304 305// Read the current kernel trace and write it to stdout. 306static void dumpTrace() 307{ 308 int traceFD = open(k_tracePath, O_RDWR); 309 if (traceFD == -1) { 310 fprintf(stderr, "error opening %s: %s (%d)\n", k_tracePath, 311 strerror(errno), errno); 312 return; 313 } 314 315 if (g_compress) { 316 z_stream zs; 317 uint8_t *in, *out; 318 int result, flush; 319 320 bzero(&zs, sizeof(zs)); 321 result = deflateInit(&zs, Z_DEFAULT_COMPRESSION); 322 if (result != Z_OK) { 323 fprintf(stderr, "error initializing zlib: %d\n", result); 324 close(traceFD); 325 return; 326 } 327 328 const size_t bufSize = 64*1024; 329 in = (uint8_t*)malloc(bufSize); 330 out = (uint8_t*)malloc(bufSize); 331 flush = Z_NO_FLUSH; 332 333 zs.next_out = out; 334 zs.avail_out = bufSize; 335 336 do { 337 338 if (zs.avail_in == 0) { 339 // More input is needed. 340 result = read(traceFD, in, bufSize); 341 if (result < 0) { 342 fprintf(stderr, "error reading trace: %s (%d)\n", 343 strerror(errno), errno); 344 result = Z_STREAM_END; 345 break; 346 } else if (result == 0) { 347 flush = Z_FINISH; 348 } else { 349 zs.next_in = in; 350 zs.avail_in = result; 351 } 352 } 353 354 if (zs.avail_out == 0) { 355 // Need to write the output. 356 result = write(STDOUT_FILENO, out, bufSize); 357 if ((size_t)result < bufSize) { 358 fprintf(stderr, "error writing deflated trace: %s (%d)\n", 359 strerror(errno), errno); 360 result = Z_STREAM_END; // skip deflate error message 361 zs.avail_out = bufSize; // skip the final write 362 break; 363 } 364 zs.next_out = out; 365 zs.avail_out = bufSize; 366 } 367 368 } while ((result = deflate(&zs, flush)) == Z_OK); 369 370 if (result != Z_STREAM_END) { 371 fprintf(stderr, "error deflating trace: %s\n", zs.msg); 372 } 373 374 if (zs.avail_out < bufSize) { 375 size_t bytes = bufSize - zs.avail_out; 376 result = write(STDOUT_FILENO, out, bytes); 377 if ((size_t)result < bytes) { 378 fprintf(stderr, "error writing deflated trace: %s (%d)\n", 379 strerror(errno), errno); 380 } 381 } 382 383 result = deflateEnd(&zs); 384 if (result != Z_OK) { 385 fprintf(stderr, "error cleaning up zlib: %d\n", result); 386 } 387 388 free(in); 389 free(out); 390 } else { 391 ssize_t sent = 0; 392 while ((sent = sendfile(STDOUT_FILENO, traceFD, NULL, 64*1024*1024)) > 0); 393 if (sent == -1) { 394 fprintf(stderr, "error dumping trace: %s (%d)\n", strerror(errno), 395 errno); 396 } 397 } 398 399 close(traceFD); 400} 401 402// Print the command usage help to stderr. 403static void showHelp(const char *cmd) 404{ 405 fprintf(stderr, "usage: %s [options]\n", cmd); 406 fprintf(stderr, "options include:\n" 407 " -b N use a trace buffer size of N KB\n" 408 " -c trace into a circular buffer\n" 409 " -d trace disk I/O\n" 410 " -f trace clock frequency changes\n" 411 " -l trace CPU frequency governor load\n" 412 " -s trace the kernel scheduler switches\n" 413 " -t N trace for N seconds [defualt 5]\n" 414 " -u trace bus utilization\n" 415 " -w trace the kernel workqueue\n" 416 " -z compress the trace dump\n"); 417} 418 419static void handleSignal(int signo) { 420 g_traceAborted = true; 421} 422 423static void registerSigHandler() { 424 struct sigaction sa; 425 sigemptyset(&sa.sa_mask); 426 sa.sa_flags = 0; 427 sa.sa_handler = handleSignal; 428 sigaction(SIGHUP, &sa, NULL); 429 sigaction(SIGINT, &sa, NULL); 430 sigaction(SIGQUIT, &sa, NULL); 431 sigaction(SIGTERM, &sa, NULL); 432} 433 434int main(int argc, char **argv) 435{ 436 bool isRoot = (getuid() == 0); 437 438 if (argc == 2 && 0 == strcmp(argv[1], "--help")) { 439 showHelp(argv[0]); 440 exit(0); 441 } 442 443 for (;;) { 444 int ret; 445 446 ret = getopt(argc, argv, "b:cidflst:uwz"); 447 448 if (ret < 0) { 449 break; 450 } 451 452 switch(ret) { 453 case 'b': 454 g_traceBufferSizeKB = atoi(optarg); 455 break; 456 457 case 'c': 458 g_traceOverwrite = true; 459 break; 460 461 case 'i': 462 g_traceCpuIdle = true; 463 break; 464 465 case 'l': 466 g_traceGovernorLoad = true; 467 break; 468 469 case 'd': 470 if (!isRoot) { 471 fprintf(stderr, "error: tracing disk activity requires root privileges\n"); 472 exit(1); 473 } 474 g_traceDisk = true; 475 break; 476 477 case 'f': 478 g_traceFrequency = true; 479 break; 480 481 case 's': 482 g_traceSchedSwitch = true; 483 break; 484 485 case 't': 486 g_traceDurationSeconds = atoi(optarg); 487 break; 488 489 case 'u': 490 if (!isRoot) { 491 fprintf(stderr, "error: tracing bus utilization requires root privileges\n"); 492 exit(1); 493 } 494 g_traceBusUtilization = true; 495 break; 496 497 case 'w': 498 if (!isRoot) { 499 fprintf(stderr, "error: tracing kernel work queues requires root privileges\n"); 500 exit(1); 501 } 502 g_traceWorkqueue = true; 503 break; 504 505 case 'z': 506 g_compress = true; 507 break; 508 509 default: 510 fprintf(stderr, "\n"); 511 showHelp(argv[0]); 512 exit(-1); 513 break; 514 } 515 } 516 517 registerSigHandler(); 518 519 bool ok = startTrace(isRoot); 520 521 if (ok) { 522 printf("capturing trace..."); 523 fflush(stdout); 524 525 // We clear the trace after starting it because tracing gets enabled for 526 // each CPU individually in the kernel. Having the beginning of the trace 527 // contain entries from only one CPU can cause "begin" entries without a 528 // matching "end" entry to show up if a task gets migrated from one CPU to 529 // another. 530 ok = clearTrace(); 531 532 if (ok) { 533 // Sleep to allow the trace to be captured. 534 struct timespec timeLeft; 535 timeLeft.tv_sec = g_traceDurationSeconds; 536 timeLeft.tv_nsec = 0; 537 do { 538 if (g_traceAborted) { 539 break; 540 } 541 } while (nanosleep(&timeLeft, &timeLeft) == -1 && errno == EINTR); 542 } 543 } 544 545 // Stop the trace and restore the default settings. 546 stopTrace(isRoot); 547 548 if (ok) { 549 if (!g_traceAborted) { 550 printf(" done\nTRACE:\n"); 551 fflush(stdout); 552 dumpTrace(); 553 } else { 554 printf("\ntrace aborted.\n"); 555 fflush(stdout); 556 } 557 clearTrace(); 558 } else { 559 fprintf(stderr, "unable to start tracing\n"); 560 } 561 562 // Reset the trace buffer size to 1. 563 setTraceBufferSizeKB(1); 564 565 return g_traceAborted ? 1 : 0; 566} 567