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