cmds/atrace/atrace.cpp

   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  #define LOG_TAG "atrace"
  18
  19 #include <errno.h>
  20 #include <fcntl.h>
  21 #include <getopt.h>
  22 #include <inttypes.h>
  23 #include <signal.h>
  24 #include <stdarg.h>
  25 #include <stdbool.h>
  26 #include <stdio.h>
  27 #include <stdlib.h>
  28 #include <string.h>
  29 #include <sys/sendfile.h>
  30 #include <time.h>
  31 #include <unistd.h>
  32 #include <zlib.h>
  33
  34 #include <binder/IBinder.h>
  35 #include <binder/IServiceManager.h>
  36 #include <binder/Parcel.h>
  37
  38 #include <cutils/properties.h>
  39
  40 #include <utils/String8.h>
  41 #include <utils/Timers.h>
  42 #include <utils/Tokenizer.h>
  43 #include <utils/Trace.h>
  44
  45 using namespace android;
  46
  47 #define NELEM(x) ((int) (sizeof(x) / sizeof((x)[0])))
  48
  49 #define MAX_SYS_FILES 10
  50 #define MAX_PACKAGES 16
  51
  52 const char* k_traceTagsProperty = "debug.atrace.tags.enableflags";
  53
  54 const char* k_traceAppsNumberProperty = "debug.atrace.app_number";
  55 const char* k_traceAppsPropertyTemplate = "debug.atrace.app_%d";
  56 const char* k_coreServiceCategory = "core_services";
  57 const char* k_coreServicesProp = "ro.atrace.core.services";
  58
  59 typedef enum { OPT, REQ } requiredness  ;
  60
  61 struct TracingCategory {
  62     // The name identifying the category.
  63     const char* name;
  64
  65     // A longer description of the category.
  66     const char* longname;
  67
  68     // The userland tracing tags that the category enables.
  69     uint64_t tags;
  70
  71     // The fname==NULL terminated list of /sys/ files that the category
  72     // enables.
  73     struct {
  74         // Whether the file must be writable in order to enable the tracing
  75         // category.
  76         requiredness required;
  77
  78         // The path to the enable file.
  79         const char* path;
  80     } sysfiles[MAX_SYS_FILES];
  81 };
  82
  83 /* Tracing categories */
  84 static const TracingCategory k_categories[] = {
  85     { "gfx",        "Graphics",         ATRACE_TAG_GRAPHICS, { } },
  86     { "input",      "Input",            ATRACE_TAG_INPUT, { } },
  87     { "view",       "View System",      ATRACE_TAG_VIEW, { } },
  88     { "webview",    "WebView",          ATRACE_TAG_WEBVIEW, { } },
  89     { "wm",         "Window Manager",   ATRACE_TAG_WINDOW_MANAGER, { } },
  90     { "am",         "Activity Manager", ATRACE_TAG_ACTIVITY_MANAGER, { } },
  91     { "sm",         "Sync Manager",     ATRACE_TAG_SYNC_MANAGER, { } },
  92     { "audio",      "Audio",            ATRACE_TAG_AUDIO, { } },
  93     { "video",      "Video",            ATRACE_TAG_VIDEO, { } },
  94     { "camera",     "Camera",           ATRACE_TAG_CAMERA, { } },
  95     { "hal",        "Hardware Modules", ATRACE_TAG_HAL, { } },
  96     { "app",        "Application",      ATRACE_TAG_APP, { } },
  97     { "res",        "Resource Loading", ATRACE_TAG_RESOURCES, { } },
  98     { "dalvik",     "Dalvik VM",        ATRACE_TAG_DALVIK, { } },
  99     { "rs",         "RenderScript",     ATRACE_TAG_RS, { } },
 100     { "bionic",     "Bionic C Library", ATRACE_TAG_BIONIC, { } },
 101     { "power",      "Power Management", ATRACE_TAG_POWER, { } },
 102     { "pm",         "Package Manager",  ATRACE_TAG_PACKAGE_MANAGER, { } },
 103     { "ss",         "System Server",    ATRACE_TAG_SYSTEM_SERVER, { } },
 104     { "database",   "Database",         ATRACE_TAG_DATABASE, { } },
 105     { "network",    "Network",          ATRACE_TAG_NETWORK, { } },
 106     { k_coreServiceCategory, "Core services", 0, { } },
 107     { "sched",      "CPU Scheduling",   0, {
 108         { REQ,      "/sys/kernel/debug/tracing/events/sched/sched_switch/enable" },
 109         { REQ,      "/sys/kernel/debug/tracing/events/sched/sched_wakeup/enable" },
 110         { OPT,      "/sys/kernel/debug/tracing/events/sched/sched_blocked_reason/enable" },
 111         { OPT,      "/sys/kernel/debug/tracing/events/sched/sched_cpu_hotplug/enable" },
 112     } },
 113     { "irq",        "IRQ Events",   0, {
 114         { REQ,      "/sys/kernel/debug/tracing/events/irq/enable" },
 115         { OPT,      "/sys/kernel/debug/tracing/events/ipi/enable" },
 116     } },
 117     { "freq",       "CPU Frequency",    0, {
 118         { REQ,      "/sys/kernel/debug/tracing/events/power/cpu_frequency/enable" },
 119         { OPT,      "/sys/kernel/debug/tracing/events/power/clock_set_rate/enable" },
 120         { OPT,      "/sys/kernel/debug/tracing/events/power/cpu_frequency_limits/enable" },
 121     } },
 122     { "membus",     "Memory Bus Utilization", 0, {
 123         { REQ,      "/sys/kernel/debug/tracing/events/memory_bus/enable" },
 124     } },
 125     { "idle",       "CPU Idle",         0, {
 126         { REQ,      "/sys/kernel/debug/tracing/events/power/cpu_idle/enable" },
 127     } },
 128     { "disk",       "Disk I/O",         0, {
 129         { OPT,      "/sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_enter/enable" },
 130         { OPT,      "/sys/kernel/debug/tracing/events/f2fs/f2fs_sync_file_exit/enable" },
 131         { OPT,      "/sys/kernel/debug/tracing/events/f2fs/f2fs_write_begin/enable" },
 132         { OPT,      "/sys/kernel/debug/tracing/events/f2fs/f2fs_write_end/enable" },
 133         { OPT,      "/sys/kernel/debug/tracing/events/ext4/ext4_da_write_begin/enable" },
 134         { OPT,      "/sys/kernel/debug/tracing/events/ext4/ext4_da_write_end/enable" },
 135         { OPT,      "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_enter/enable" },
 136         { OPT,      "/sys/kernel/debug/tracing/events/ext4/ext4_sync_file_exit/enable" },
 137         { REQ,      "/sys/kernel/debug/tracing/events/block/block_rq_issue/enable" },
 138         { REQ,      "/sys/kernel/debug/tracing/events/block/block_rq_complete/enable" },
 139     } },
 140     { "mmc",        "eMMC commands",    0, {
 141         { REQ,      "/sys/kernel/debug/tracing/events/mmc/enable" },
 142     } },
 143     { "load",       "CPU Load",         0, {
 144         { REQ,      "/sys/kernel/debug/tracing/events/cpufreq_interactive/enable" },
 145     } },
 146     { "sync",       "Synchronization",  0, {
 147         { REQ,      "/sys/kernel/debug/tracing/events/sync/enable" },
 148     } },
 149     { "workq",      "Kernel Workqueues", 0, {
 150         { REQ,      "/sys/kernel/debug/tracing/events/workqueue/enable" },
 151     } },
 152     { "memreclaim", "Kernel Memory Reclaim", 0, {
 153         { REQ,      "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_direct_reclaim_begin/enable" },
 154         { REQ,      "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_direct_reclaim_end/enable" },
 155         { REQ,      "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_kswapd_wake/enable" },
 156         { REQ,      "/sys/kernel/debug/tracing/events/vmscan/mm_vmscan_kswapd_sleep/enable" },
 157     } },
 158     { "regulators",  "Voltage and Current Regulators", 0, {
 159         { REQ,      "/sys/kernel/debug/tracing/events/regulator/enable" },
 160     } },
 161     { "binder_driver", "Binder Kernel driver", 0, {
 162         { REQ,      "/sys/kernel/debug/tracing/events/binder/binder_transaction/enable" },
 163         { REQ,      "/sys/kernel/debug/tracing/events/binder/binder_transaction_received/enable" },
 164     } },
 165     { "binder_lock", "Binder global lock trace", 0, {
 166         { REQ,      "/sys/kernel/debug/tracing/events/binder/binder_lock/enable" },
 167         { REQ,      "/sys/kernel/debug/tracing/events/binder/binder_locked/enable" },
 168         { REQ,      "/sys/kernel/debug/tracing/events/binder/binder_unlock/enable" },
 169     } },
 170     { "pagecache",  "Page cache", 0, {
 171         { REQ,      "/sys/kernel/debug/tracing/events/filemap/enable" },
 172     } },
 173 };
 174
 175 /* Command line options */
 176 static int g_traceDurationSeconds = 5;
 177 static bool g_traceOverwrite = false;
 178 static int g_traceBufferSizeKB = 2048;
 179 static bool g_compress = false;
 180 static bool g_nohup = false;
 181 static int g_initialSleepSecs = 0;
 182 static const char* g_categoriesFile = NULL;
 183 static const char* g_kernelTraceFuncs = NULL;
 184 static const char* g_debugAppCmdLine = "";
 185 static const char* g_outputFile = nullptr;
 186
 187 /* Global state */
 188 static bool g_traceAborted = false;
 189 static bool g_categoryEnables[NELEM(k_categories)] = {};
 190
 191 /* Sys file paths */
 192 static const char* k_traceClockPath =
 193     "/sys/kernel/debug/tracing/trace_clock";
 194
 195 static const char* k_traceBufferSizePath =
 196     "/sys/kernel/debug/tracing/buffer_size_kb";
 197
 198 static const char* k_tracingOverwriteEnablePath =
 199     "/sys/kernel/debug/tracing/options/overwrite";
 200
 201 static const char* k_currentTracerPath =
 202     "/sys/kernel/debug/tracing/current_tracer";
 203
 204 static const char* k_printTgidPath =
 205     "/sys/kernel/debug/tracing/options/print-tgid";
 206
 207 static const char* k_funcgraphAbsTimePath =
 208     "/sys/kernel/debug/tracing/options/funcgraph-abstime";
 209
 210 static const char* k_funcgraphCpuPath =
 211     "/sys/kernel/debug/tracing/options/funcgraph-cpu";
 212
 213 static const char* k_funcgraphProcPath =
 214     "/sys/kernel/debug/tracing/options/funcgraph-proc";
 215
 216 static const char* k_funcgraphFlatPath =
 217     "/sys/kernel/debug/tracing/options/funcgraph-flat";
 218
 219 static const char* k_funcgraphDurationPath =
 220     "/sys/kernel/debug/tracing/options/funcgraph-duration";
 221
 222 static const char* k_ftraceFilterPath =
 223     "/sys/kernel/debug/tracing/set_ftrace_filter";
 224
 225 static const char* k_tracingOnPath =
 226     "/sys/kernel/debug/tracing/tracing_on";
 227
 228 static const char* k_tracePath =
 229     "/sys/kernel/debug/tracing/trace";
 230
 231 static const char* k_traceStreamPath =
 232     "/sys/kernel/debug/tracing/trace_pipe";
 233
 234 static const char* k_traceMarkerPath =
 235     "/sys/kernel/debug/tracing/trace_marker";
 236
 237 // Check whether a file exists.
 238 static bool fileExists(const char* filename) {
 239     return access(filename, F_OK) != -1;
 240 }
 241
 242 // Check whether a file is writable.
 243 static bool fileIsWritable(const char* filename) {
 244     return access(filename, W_OK) != -1;
 245 }
 246
 247 // Truncate a file.
 248 static bool truncateFile(const char* path)
 249 {
 250     // This uses creat rather than truncate because some of the debug kernel
 251     // device nodes (e.g. k_ftraceFilterPath) currently aren't changed by
 252     // calls to truncate, but they are cleared by calls to creat.
 253     int traceFD = creat(path, 0);
 254     if (traceFD == -1) {
 255         fprintf(stderr, "error truncating %s: %s (%d)\n", path,
 256             strerror(errno), errno);
 257         return false;
 258     }
 259
 260     close(traceFD);
 261
 262     return true;
 263 }
 264
 265 static bool _writeStr(const char* filename, const char* str, int flags)
 266 {
 267     int fd = open(filename, flags);
 268     if (fd == -1) {
 269         fprintf(stderr, "error opening %s: %s (%d)\n", filename,
 270                 strerror(errno), errno);
 271         return false;
 272     }
 273
 274     bool ok = true;
 275     ssize_t len = strlen(str);
 276     if (write(fd, str, len) != len) {
 277         fprintf(stderr, "error writing to %s: %s (%d)\n", filename,
 278                 strerror(errno), errno);
 279         ok = false;
 280     }
 281
 282     close(fd);
 283
 284     return ok;
 285 }
 286
 287 // Write a string to a file, returning true if the write was successful.
 288 static bool writeStr(const char* filename, const char* str)
 289 {
 290     return _writeStr(filename, str, O_WRONLY);
 291 }
 292
 293 // Append a string to a file, returning true if the write was successful.
 294 static bool appendStr(const char* filename, const char* str)
 295 {
 296     return _writeStr(filename, str, O_APPEND|O_WRONLY);
 297 }
 298
 299 static void writeClockSyncMarker()
 300 {
 301   char buffer[128];
 302   int len = 0;
 303   int fd = open(k_traceMarkerPath, O_WRONLY);
 304   if (fd == -1) {
 305       fprintf(stderr, "error opening %s: %s (%d)\n", k_traceMarkerPath,
 306               strerror(errno), errno);
 307       return;
 308   }
 309   float now_in_seconds = systemTime(CLOCK_MONOTONIC) / 1000000000.0f;
 310
 311   len = snprintf(buffer, 128, "trace_event_clock_sync: parent_ts=%f\n", now_in_seconds);
 312   if (write(fd, buffer, len) != len) {
 313       fprintf(stderr, "error writing clock sync marker %s (%d)\n", strerror(errno), errno);
 314   }
 315
 316   int64_t realtime_in_ms = systemTime(CLOCK_REALTIME) / 1000000;
 317   len = snprintf(buffer, 128, "trace_event_clock_sync: realtime_ts=%" PRId64 "\n", realtime_in_ms);
 318   if (write(fd, buffer, len) != len) {
 319       fprintf(stderr, "error writing clock sync marker %s (%d)\n", strerror(errno), errno);
 320   }
 321
 322   close(fd);
 323 }
 324
 325 // Enable or disable a kernel option by writing a "1" or a "0" into a /sys
 326 // file.
 327 static bool setKernelOptionEnable(const char* filename, bool enable)
 328 {
 329     return writeStr(filename, enable ? "1" : "0");
 330 }
 331
 332 // Check whether the category is supported on the device with the current
 333 // rootness.  A category is supported only if all its required /sys/ files are
 334 // writable and if enabling the category will enable one or more tracing tags
 335 // or /sys/ files.
 336 static bool isCategorySupported(const TracingCategory& category)
 337 {
 338     if (strcmp(category.name, k_coreServiceCategory) == 0) {
 339         char value[PROPERTY_VALUE_MAX];
 340         property_get(k_coreServicesProp, value, "");
 341         return strlen(value) != 0;
 342     }
 343
 344     bool ok = category.tags != 0;
 345     for (int i = 0; i < MAX_SYS_FILES; i++) {
 346         const char* path = category.sysfiles[i].path;
 347         bool req = category.sysfiles[i].required == REQ;
 348         if (path != NULL) {
 349             if (req) {
 350                 if (!fileIsWritable(path)) {
 351                     return false;
 352                 } else {
 353                     ok = true;
 354                 }
 355             } else {
 356                 ok |= fileIsWritable(path);
 357             }
 358         }
 359     }
 360     return ok;
 361 }
 362
 363 // Check whether the category would be supported on the device if the user
 364 // were root.  This function assumes that root is able to write to any file
 365 // that exists.  It performs the same logic as isCategorySupported, but it
 366 // uses file existance rather than writability in the /sys/ file checks.
 367 static bool isCategorySupportedForRoot(const TracingCategory& category)
 368 {
 369     bool ok = category.tags != 0;
 370     for (int i = 0; i < MAX_SYS_FILES; i++) {
 371         const char* path = category.sysfiles[i].path;
 372         bool req = category.sysfiles[i].required == REQ;
 373         if (path != NULL) {
 374             if (req) {
 375                 if (!fileExists(path)) {
 376                     return false;
 377                 } else {
 378                     ok = true;
 379                 }
 380             } else {
 381                 ok |= fileExists(path);
 382             }
 383         }
 384     }
 385     return ok;
 386 }
 387
 388 // Enable or disable overwriting of the kernel trace buffers.  Disabling this
 389 // will cause tracing to stop once the trace buffers have filled up.
 390 static bool setTraceOverwriteEnable(bool enable)
 391 {
 392     return setKernelOptionEnable(k_tracingOverwriteEnablePath, enable);
 393 }
 394
 395 // Enable or disable kernel tracing.
 396 static bool setTracingEnabled(bool enable)
 397 {
 398     return setKernelOptionEnable(k_tracingOnPath, enable);
 399 }
 400
 401 // Clear the contents of the kernel trace.
 402 static bool clearTrace()
 403 {
 404     return truncateFile(k_tracePath);
 405 }
 406
 407 // Set the size of the kernel's trace buffer in kilobytes.
 408 static bool setTraceBufferSizeKB(int size)
 409 {
 410     char str[32] = "1";
 411     int len;
 412     if (size < 1) {
 413         size = 1;
 414     }
 415     snprintf(str, 32, "%d", size);
 416     return writeStr(k_traceBufferSizePath, str);
 417 }
 418
 419 // Read the trace_clock sysfs file and return true if it matches the requested
 420 // value.  The trace_clock file format is:
 421 // local [global] counter uptime perf
 422 static bool isTraceClock(const char *mode)
 423 {
 424     int fd = open(k_traceClockPath, O_RDONLY);
 425     if (fd == -1) {
 426         fprintf(stderr, "error opening %s: %s (%d)\n", k_traceClockPath,
 427             strerror(errno), errno);
 428         return false;
 429     }
 430
 431     char buf[4097];
 432     ssize_t n = read(fd, buf, 4096);
 433     close(fd);
 434     if (n == -1) {
 435         fprintf(stderr, "error reading %s: %s (%d)\n", k_traceClockPath,
 436             strerror(errno), errno);
 437         return false;
 438     }
 439     buf[n] = '\0';
 440
 441     char *start = strchr(buf, '[');
 442     if (start == NULL) {
 443         return false;
 444     }
 445     start++;
 446
 447     char *end = strchr(start, ']');
 448     if (end == NULL) {
 449         return false;
 450     }
 451     *end = '\0';
 452
 453     return strcmp(mode, start) == 0;
 454 }
 455
 456 // Enable or disable the kernel's use of the global clock.  Disabling the global
 457 // clock will result in the kernel using a per-CPU local clock.
 458 // Any write to the trace_clock sysfs file will reset the buffer, so only
 459 // update it if the requested value is not the current value.
 460 static bool setGlobalClockEnable(bool enable)
 461 {
 462     const char *clock = enable ? "global" : "local";
 463
 464     if (isTraceClock(clock)) {
 465         return true;
 466     }
 467
 468     return writeStr(k_traceClockPath, clock);
 469 }
 470
 471 static bool setPrintTgidEnableIfPresent(bool enable)
 472 {
 473     if (fileExists(k_printTgidPath)) {
 474         return setKernelOptionEnable(k_printTgidPath, enable);
 475     }
 476     return true;
 477 }
 478
 479 // Poke all the binder-enabled processes in the system to get them to re-read
 480 // their system properties.
 481 static bool pokeBinderServices()
 482 {
 483     sp<IServiceManager> sm = defaultServiceManager();
 484     Vector<String16> services = sm->listServices();
 485     for (size_t i = 0; i < services.size(); i++) {
 486         sp<IBinder> obj = sm->checkService(services[i]);
 487         if (obj != NULL) {
 488             Parcel data;
 489             if (obj->transact(IBinder::SYSPROPS_TRANSACTION, data,
 490                     NULL, 0) != OK) {
 491                 if (false) {
 492                     // XXX: For some reason this fails on tablets trying to
 493                     // poke the "phone" service.  It's not clear whether some
 494                     // are expected to fail.
 495                     String8 svc(services[i]);
 496                     fprintf(stderr, "error poking binder service %s\n",
 497                         svc.string());
 498                     return false;
 499                 }
 500             }
 501         }
 502     }
 503     return true;
 504 }
 505
 506 // Set the trace tags that userland tracing uses, and poke the running
 507 // processes to pick up the new value.
 508 static bool setTagsProperty(uint64_t tags)
 509 {
 510     char buf[PROPERTY_VALUE_MAX];
 511     snprintf(buf, sizeof(buf), "%#" PRIx64, tags);
 512     if (property_set(k_traceTagsProperty, buf) < 0) {
 513         fprintf(stderr, "error setting trace tags system property\n");
 514         return false;
 515     }
 516     return true;
 517 }
 518
 519 static void clearAppProperties()
 520 {
 521     char buf[PROPERTY_KEY_MAX];
 522     for (int i = 0; i < MAX_PACKAGES; i++) {
 523         snprintf(buf, sizeof(buf), k_traceAppsPropertyTemplate, i);
 524         if (property_set(buf, "") < 0) {
 525             fprintf(stderr, "failed to clear system property: %s\n", buf);
 526         }
 527     }
 528     if (property_set(k_traceAppsNumberProperty, "") < 0) {
 529         fprintf(stderr, "failed to clear system property: %s",
 530               k_traceAppsNumberProperty);
 531     }
 532 }
 533
 534 // Set the system property that indicates which apps should perform
 535 // application-level tracing.
 536 static bool setAppCmdlineProperty(const char* cmdline)
 537 {
 538     char buf[PROPERTY_KEY_MAX];
 539     int i = 0;
 540     const char* start = cmdline;
 541     while (start != NULL) {
 542         if (i == MAX_PACKAGES) {
 543             fprintf(stderr, "error: only 16 packages could be traced at once\n");
 544             clearAppProperties();
 545             return false;
 546         }
 547         char* end = strchr(start, ',');
 548         if (end != NULL) {
 549             *end = '\0';
 550             end++;
 551         }
 552         snprintf(buf, sizeof(buf), k_traceAppsPropertyTemplate, i);
 553         if (property_set(buf, start) < 0) {
 554             fprintf(stderr, "error setting trace app %d property to %s\n", i, buf);
 555             clearAppProperties();
 556             return false;
 557         }
 558         start = end;
 559         i++;
 560     }
 561
 562     snprintf(buf, sizeof(buf), "%d", i);
 563     if (property_set(k_traceAppsNumberProperty, buf) < 0) {
 564         fprintf(stderr, "error setting trace app number property to %s\n", buf);
 565         clearAppProperties();
 566         return false;
 567     }
 568     return true;
 569 }
 570
 571 // Disable all /sys/ enable files.
 572 static bool disableKernelTraceEvents() {
 573     bool ok = true;
 574     for (int i = 0; i < NELEM(k_categories); i++) {
 575         const TracingCategory &c = k_categories[i];
 576         for (int j = 0; j < MAX_SYS_FILES; j++) {
 577             const char* path = c.sysfiles[j].path;
 578             if (path != NULL && fileIsWritable(path)) {
 579                 ok &= setKernelOptionEnable(path, false);
 580             }
 581         }
 582     }
 583     return ok;
 584 }
 585
 586 // Verify that the comma separated list of functions are being traced by the
 587 // kernel.
 588 static bool verifyKernelTraceFuncs(const char* funcs)
 589 {
 590     int fd = open(k_ftraceFilterPath, O_RDONLY);
 591     if (fd == -1) {
 592         fprintf(stderr, "error opening %s: %s (%d)\n", k_ftraceFilterPath,
 593             strerror(errno), errno);
 594         return false;
 595     }
 596
 597     char buf[4097];
 598     ssize_t n = read(fd, buf, 4096);
 599     close(fd);
 600     if (n == -1) {
 601         fprintf(stderr, "error reading %s: %s (%d)\n", k_ftraceFilterPath,
 602             strerror(errno), errno);
 603         return false;
 604     }
 605
 606     buf[n] = '\0';
 607     String8 funcList = String8::format("\n%s", buf);
 608
 609     // Make sure that every function listed in funcs is in the list we just
 610     // read from the kernel, except for wildcard inputs.
 611     bool ok = true;
 612     char* myFuncs = strdup(funcs);
 613     char* func = strtok(myFuncs, ",");
 614     while (func) {
 615         if (!strchr(func, '*')) {
 616             String8 fancyFunc = String8::format("\n%s\n", func);
 617             bool found = funcList.find(fancyFunc.string(), 0) >= 0;
 618             if (!found || func[0] == '\0') {
 619                 fprintf(stderr, "error: \"%s\" is not a valid kernel function "
 620                         "to trace.\n", func);
 621                 ok = false;
 622             }
 623         }
 624         func = strtok(NULL, ",");
 625     }
 626     free(myFuncs);
 627
 628     return ok;
 629 }
 630
 631 // Set the comma separated list of functions that the kernel is to trace.
 632 static bool setKernelTraceFuncs(const char* funcs)
 633 {
 634     bool ok = true;
 635
 636     if (funcs == NULL || funcs[0] == '\0') {
 637         // Disable kernel function tracing.
 638         if (fileIsWritable(k_currentTracerPath)) {
 639             ok &= writeStr(k_currentTracerPath, "nop");
 640         }
 641         if (fileIsWritable(k_ftraceFilterPath)) {
 642             ok &= truncateFile(k_ftraceFilterPath);
 643         }
 644     } else {
 645         // Enable kernel function tracing.
 646         ok &= writeStr(k_currentTracerPath, "function_graph");
 647         ok &= setKernelOptionEnable(k_funcgraphAbsTimePath, true);
 648         ok &= setKernelOptionEnable(k_funcgraphCpuPath, true);
 649         ok &= setKernelOptionEnable(k_funcgraphProcPath, true);
 650         ok &= setKernelOptionEnable(k_funcgraphFlatPath, true);
 651
 652         // Set the requested filter functions.
 653         ok &= truncateFile(k_ftraceFilterPath);
 654         char* myFuncs = strdup(funcs);
 655         char* func = strtok(myFuncs, ",");
 656         while (func) {
 657             ok &= appendStr(k_ftraceFilterPath, func);
 658             func = strtok(NULL, ",");
 659         }
 660         free(myFuncs);
 661
 662         // Verify that the set functions are being traced.
 663         if (ok) {
 664             ok &= verifyKernelTraceFuncs(funcs);
 665         }
 666     }
 667
 668     return ok;
 669 }
 670
 671 static bool setCategoryEnable(const char* name, bool enable)
 672 {
 673     for (int i = 0; i < NELEM(k_categories); i++) {
 674         const TracingCategory& c = k_categories[i];
 675         if (strcmp(name, c.name) == 0) {
 676             if (isCategorySupported(c)) {
 677                 g_categoryEnables[i] = enable;
 678                 return true;
 679             } else {
 680                 if (isCategorySupportedForRoot(c)) {
 681                     fprintf(stderr, "error: category \"%s\" requires root "
 682                             "privileges.\n", name);
 683                 } else {
 684                     fprintf(stderr, "error: category \"%s\" is not supported "
 685                             "on this device.\n", name);
 686                 }
 687                 return false;
 688             }
 689         }
 690     }
 691     fprintf(stderr, "error: unknown tracing category \"%s\"\n", name);
 692     return false;
 693 }
 694
 695 static bool setCategoriesEnableFromFile(const char* categories_file)
 696 {
 697     if (!categories_file) {
 698         return true;
 699     }
 700     Tokenizer* tokenizer = NULL;
 701     if (Tokenizer::open(String8(categories_file), &tokenizer) != NO_ERROR) {
 702         return false;
 703     }
 704     bool ok = true;
 705     while (!tokenizer->isEol()) {
 706         String8 token = tokenizer->nextToken(" ");
 707         if (token.isEmpty()) {
 708             tokenizer->skipDelimiters(" ");
 709             continue;
 710         }
 711         ok &= setCategoryEnable(token.string(), true);
 712     }
 713     delete tokenizer;
 714     return ok;
 715 }
 716
 717 // Set all the kernel tracing settings to the desired state for this trace
 718 // capture.
 719 static bool setUpTrace()
 720 {
 721     bool ok = true;
 722
 723     // Set up the tracing options.
 724     ok &= setCategoriesEnableFromFile(g_categoriesFile);
 725     ok &= setTraceOverwriteEnable(g_traceOverwrite);
 726     ok &= setTraceBufferSizeKB(g_traceBufferSizeKB);
 727     ok &= setGlobalClockEnable(true);
 728     ok &= setPrintTgidEnableIfPresent(true);
 729     ok &= setKernelTraceFuncs(g_kernelTraceFuncs);
 730
 731     // Set up the tags property.
 732     uint64_t tags = 0;
 733     for (int i = 0; i < NELEM(k_categories); i++) {
 734         if (g_categoryEnables[i]) {
 735             const TracingCategory &c = k_categories[i];
 736             tags |= c.tags;
 737         }
 738     }
 739     ok &= setTagsProperty(tags);
 740
 741     bool coreServicesTagEnabled = false;
 742     for (int i = 0; i < NELEM(k_categories); i++) {
 743         if (strcmp(k_categories[i].name, k_coreServiceCategory) == 0) {
 744             coreServicesTagEnabled = g_categoryEnables[i];
 745         }
 746     }
 747
 748     std::string packageList(g_debugAppCmdLine);
 749     if (coreServicesTagEnabled) {
 750         char value[PROPERTY_VALUE_MAX];
 751         property_get(k_coreServicesProp, value, "");
 752         if (!packageList.empty()) {
 753             packageList += ",";
 754         }
 755         packageList += value;
 756     }
 757     ok &= setAppCmdlineProperty(packageList.data());
 758     ok &= pokeBinderServices();
 759
 760     // Disable all the sysfs enables.  This is done as a separate loop from
 761     // the enables to allow the same enable to exist in multiple categories.
 762     ok &= disableKernelTraceEvents();
 763
 764     // Enable all the sysfs enables that are in an enabled category.
 765     for (int i = 0; i < NELEM(k_categories); i++) {
 766         if (g_categoryEnables[i]) {
 767             const TracingCategory &c = k_categories[i];
 768             for (int j = 0; j < MAX_SYS_FILES; j++) {
 769                 const char* path = c.sysfiles[j].path;
 770                 bool required = c.sysfiles[j].required == REQ;
 771                 if (path != NULL) {
 772                     if (fileIsWritable(path)) {
 773                         ok &= setKernelOptionEnable(path, true);
 774                     } else if (required) {
 775                         fprintf(stderr, "error writing file %s\n", path);
 776                         ok = false;
 777                     }
 778                 }
 779             }
 780         }
 781     }
 782
 783     return ok;
 784 }
 785
 786 // Reset all the kernel tracing settings to their default state.
 787 static void cleanUpTrace()
 788 {
 789     // Disable all tracing that we're able to.
 790     disableKernelTraceEvents();
 791
 792     // Reset the system properties.
 793     setTagsProperty(0);
 794     clearAppProperties();
 795     pokeBinderServices();
 796
 797     // Set the options back to their defaults.
 798     setTraceOverwriteEnable(true);
 799     setTraceBufferSizeKB(1);
 800     setGlobalClockEnable(false);
 801     setPrintTgidEnableIfPresent(false);
 802     setKernelTraceFuncs(NULL);
 803 }
 804
 805
 806 // Enable tracing in the kernel.
 807 static bool startTrace()
 808 {
 809     return setTracingEnabled(true);
 810 }
 811
 812 // Disable tracing in the kernel.
 813 static void stopTrace()
 814 {
 815     setTracingEnabled(false);
 816 }
 817
 818 // Read data from the tracing pipe and forward to stdout
 819 static void streamTrace()
 820 {
 821     char trace_data[4096];
 822     int traceFD = open(k_traceStreamPath, O_RDWR);
 823     if (traceFD == -1) {
 824         fprintf(stderr, "error opening %s: %s (%d)\n", k_traceStreamPath,
 825                 strerror(errno), errno);
 826         return;
 827     }
 828     while (!g_traceAborted) {
 829         ssize_t bytes_read = read(traceFD, trace_data, 4096);
 830         if (bytes_read > 0) {
 831             write(STDOUT_FILENO, trace_data, bytes_read);
 832             fflush(stdout);
 833         } else {
 834             if (!g_traceAborted) {
 835                 fprintf(stderr, "read returned %zd bytes err %d (%s)\n",
 836                         bytes_read, errno, strerror(errno));
 837             }
 838             break;
 839         }
 840     }
 841 }
 842
 843 // Read the current kernel trace and write it to stdout.
 844 static void dumpTrace(int outFd)
 845 {
 846     ALOGI("Dumping trace");
 847     int traceFD = open(k_tracePath, O_RDWR);
 848     if (traceFD == -1) {
 849         fprintf(stderr, "error opening %s: %s (%d)\n", k_tracePath,
 850                 strerror(errno), errno);
 851         return;
 852     }
 853
 854     if (g_compress) {
 855         z_stream zs;
 856         uint8_t *in, *out;
 857         int result, flush;
 858
 859         memset(&zs, 0, sizeof(zs));
 860         result = deflateInit(&zs, Z_DEFAULT_COMPRESSION);
 861         if (result != Z_OK) {
 862             fprintf(stderr, "error initializing zlib: %d\n", result);
 863             close(traceFD);
 864             return;
 865         }
 866
 867         const size_t bufSize = 64*1024;
 868         in = (uint8_t*)malloc(bufSize);
 869         out = (uint8_t*)malloc(bufSize);
 870         flush = Z_NO_FLUSH;
 871
 872         zs.next_out = out;
 873         zs.avail_out = bufSize;
 874
 875         do {
 876
 877             if (zs.avail_in == 0) {
 878                 // More input is needed.
 879                 result = read(traceFD, in, bufSize);
 880                 if (result < 0) {
 881                     fprintf(stderr, "error reading trace: %s (%d)\n",
 882                             strerror(errno), errno);
 883                     result = Z_STREAM_END;
 884                     break;
 885                 } else if (result == 0) {
 886                     flush = Z_FINISH;
 887                 } else {
 888                     zs.next_in = in;
 889                     zs.avail_in = result;
 890                 }
 891             }
 892
 893             if (zs.avail_out == 0) {
 894                 // Need to write the output.
 895                 result = write(outFd, out, bufSize);
 896                 if ((size_t)result < bufSize) {
 897                     fprintf(stderr, "error writing deflated trace: %s (%d)\n",
 898                             strerror(errno), errno);
 899                     result = Z_STREAM_END; // skip deflate error message
 900                     zs.avail_out = bufSize; // skip the final write
 901                     break;
 902                 }
 903                 zs.next_out = out;
 904                 zs.avail_out = bufSize;
 905             }
 906
 907         } while ((result = deflate(&zs, flush)) == Z_OK);
 908
 909         if (result != Z_STREAM_END) {
 910             fprintf(stderr, "error deflating trace: %s\n", zs.msg);
 911         }
 912
 913         if (zs.avail_out < bufSize) {
 914             size_t bytes = bufSize - zs.avail_out;
 915             result = write(outFd, out, bytes);
 916             if ((size_t)result < bytes) {
 917                 fprintf(stderr, "error writing deflated trace: %s (%d)\n",
 918                         strerror(errno), errno);
 919             }
 920         }
 921
 922         result = deflateEnd(&zs);
 923         if (result != Z_OK) {
 924             fprintf(stderr, "error cleaning up zlib: %d\n", result);
 925         }
 926
 927         free(in);
 928         free(out);
 929     } else {
 930         ssize_t sent = 0;
 931         while ((sent = sendfile(outFd, traceFD, NULL, 64*1024*1024)) > 0);
 932         if (sent == -1) {
 933             fprintf(stderr, "error dumping trace: %s (%d)\n", strerror(errno),
 934                     errno);
 935         }
 936     }
 937
 938     close(traceFD);
 939 }
 940
 941 static void handleSignal(int /*signo*/)
 942 {
 943     if (!g_nohup) {
 944         g_traceAborted = true;
 945     }
 946 }
 947
 948 static void registerSigHandler()
 949 {
 950     struct sigaction sa;
 951     sigemptyset(&sa.sa_mask);
 952     sa.sa_flags = 0;
 953     sa.sa_handler = handleSignal;
 954     sigaction(SIGHUP, &sa, NULL);
 955     sigaction(SIGINT, &sa, NULL);
 956     sigaction(SIGQUIT, &sa, NULL);
 957     sigaction(SIGTERM, &sa, NULL);
 958 }
 959
 960 static void listSupportedCategories()
 961 {
 962     for (int i = 0; i < NELEM(k_categories); i++) {
 963         const TracingCategory& c = k_categories[i];
 964         if (isCategorySupported(c)) {
 965             printf("  %10s - %s\n", c.name, c.longname);
 966         }
 967     }
 968 }
 969
 970 // Print the command usage help to stderr.
 971 static void showHelp(const char *cmd)
 972 {
 973     fprintf(stderr, "usage: %s [options] [categories...]\n", cmd);
 974     fprintf(stderr, "options include:\n"
 975                     "  -a appname      enable app-level tracing for a comma "
 976                         "separated list of cmdlines\n"
 977                     "  -b N            use a trace buffer size of N KB\n"
 978                     "  -c              trace into a circular buffer\n"
 979                     "  -f filename     use the categories written in a file as space-separated\n"
 980                     "                    values in a line\n"
 981                     "  -k fname,...    trace the listed kernel functions\n"
 982                     "  -n              ignore signals\n"
 983                     "  -s N            sleep for N seconds before tracing [default 0]\n"
 984                     "  -t N            trace for N seconds [defualt 5]\n"
 985                     "  -z              compress the trace dump\n"
 986                     "  --async_start   start circular trace and return immediatly\n"
 987                     "  --async_dump    dump the current contents of circular trace buffer\n"
 988                     "  --async_stop    stop tracing and dump the current contents of circular\n"
 989                     "                    trace buffer\n"
 990                     "  --stream        stream trace to stdout as it enters the trace buffer\n"
 991                     "                    Note: this can take significant CPU time, and is best\n"
 992                     "                    used for measuring things that are not affected by\n"
 993                     "                    CPU performance, like pagecache usage.\n"
 994                     "  --list_categories\n"
 995                     "                  list the available tracing categories\n"
 996                     " -o filename      write the trace to the specified file instead\n"
 997                     "                    of stdout.\n"
 998             );
 999 }
1000
1001 int main(int argc, char **argv)
1002 {
1003     bool async = false;
1004     bool traceStart = true;
1005     bool traceStop = true;
1006     bool traceDump = true;
1007     bool traceStream = false;
1008
1009     if (argc == 2 && 0 == strcmp(argv[1], "--help")) {
1010         showHelp(argv[0]);
1011         exit(0);
1012     }
1013
1014     for (;;) {
1015         int ret;
1016         int option_index = 0;
1017         static struct option long_options[] = {
1018             {"async_start",     no_argument, 0,  0 },
1019             {"async_stop",      no_argument, 0,  0 },
1020             {"async_dump",      no_argument, 0,  0 },
1021             {"list_categories", no_argument, 0,  0 },
1022             {"stream",          no_argument, 0,  0 },
1023             {           0,                0, 0,  0 }
1024         };
1025
1026         ret = getopt_long(argc, argv, "a:b:cf:k:ns:t:zo:",
1027                           long_options, &option_index);
1028
1029         if (ret < 0) {
1030             for (int i = optind; i < argc; i++) {
1031                 if (!setCategoryEnable(argv[i], true)) {
1032                     fprintf(stderr, "error enabling tracing category \"%s\"\n", argv[i]);
1033                     exit(1);
1034                 }
1035             }
1036             break;
1037         }
1038
1039         switch(ret) {
1040             case 'a':
1041                 g_debugAppCmdLine = optarg;
1042             break;
1043
1044             case 'b':
1045                 g_traceBufferSizeKB = atoi(optarg);
1046             break;
1047
1048             case 'c':
1049                 g_traceOverwrite = true;
1050             break;
1051
1052             case 'f':
1053                 g_categoriesFile = optarg;
1054             break;
1055
1056             case 'k':
1057                 g_kernelTraceFuncs = optarg;
1058             break;
1059
1060             case 'n':
1061                 g_nohup = true;
1062             break;
1063
1064             case 's':
1065                 g_initialSleepSecs = atoi(optarg);
1066             break;
1067
1068             case 't':
1069                 g_traceDurationSeconds = atoi(optarg);
1070             break;
1071
1072             case 'z':
1073                 g_compress = true;
1074             break;
1075
1076             case 'o':
1077                 g_outputFile = optarg;
1078             break;
1079
1080             case 0:
1081                 if (!strcmp(long_options[option_index].name, "async_start")) {
1082                     async = true;
1083                     traceStop = false;
1084                     traceDump = false;
1085                     g_traceOverwrite = true;
1086                 } else if (!strcmp(long_options[option_index].name, "async_stop")) {
1087                     async = true;
1088                     traceStart = false;
1089                 } else if (!strcmp(long_options[option_index].name, "async_dump")) {
1090                     async = true;
1091                     traceStart = false;
1092                     traceStop = false;
1093                 } else if (!strcmp(long_options[option_index].name, "stream")) {
1094                     traceStream = true;
1095                     traceDump = false;
1096                 } else if (!strcmp(long_options[option_index].name, "list_categories")) {
1097                     listSupportedCategories();
1098                     exit(0);
1099                 }
1100             break;
1101
1102             default:
1103                 fprintf(stderr, "\n");
1104                 showHelp(argv[0]);
1105                 exit(-1);
1106             break;
1107         }
1108     }
1109
1110     registerSigHandler();
1111
1112     if (g_initialSleepSecs > 0) {
1113         sleep(g_initialSleepSecs);
1114     }
1115
1116     bool ok = true;
1117     ok &= setUpTrace();
1118     ok &= startTrace();
1119
1120     if (ok && traceStart) {
1121         if (!traceStream) {
1122             printf("capturing trace...");
1123             fflush(stdout);
1124         }
1125
1126         // We clear the trace after starting it because tracing gets enabled for
1127         // each CPU individually in the kernel. Having the beginning of the trace
1128         // contain entries from only one CPU can cause "begin" entries without a
1129         // matching "end" entry to show up if a task gets migrated from one CPU to
1130         // another.
1131         ok = clearTrace();
1132
1133         writeClockSyncMarker();
1134         if (ok && !async && !traceStream) {
1135             // Sleep to allow the trace to be captured.
1136             struct timespec timeLeft;
1137             timeLeft.tv_sec = g_traceDurationSeconds;
1138             timeLeft.tv_nsec = 0;
1139             do {
1140                 if (g_traceAborted) {
1141                     break;
1142                 }
1143             } while (nanosleep(&timeLeft, &timeLeft) == -1 && errno == EINTR);
1144         }
1145
1146         if (traceStream) {
1147             streamTrace();
1148         }
1149     }
1150
1151     // Stop the trace and restore the default settings.
1152     if (traceStop)
1153         stopTrace();
1154
1155     if (ok && traceDump) {
1156         if (!g_traceAborted) {
1157             printf(" done\n");
1158             fflush(stdout);
1159             int outFd = STDOUT_FILENO;
1160             if (g_outputFile) {
1161                 outFd = open(g_outputFile, O_WRONLY | O_CREAT);
1162             }
1163             if (outFd == -1) {
1164                 printf("Failed to open '%s', err=%d", g_outputFile, errno);
1165             } else {
1166                 dprintf(outFd, "TRACE:\n");
1167                 dumpTrace(outFd);
1168                 if (g_outputFile) {
1169                     close(outFd);
1170                 }
1171             }
1172         } else {
1173             printf("\ntrace aborted.\n");
1174             fflush(stdout);
1175         }
1176         clearTrace();
1177     } else if (!ok) {
1178         fprintf(stderr, "unable to start tracing\n");
1179     }
1180
1181     // Reset the trace buffer size to 1.
1182     if (traceStop)
1183         cleanUpTrace();
1184
1185     return g_traceAborted ? 1 : 0;
1186 }