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