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