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