atrace.c revision eb213e7201b7288df2d2ec7e785349d993828bd3 
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/* Command line options */
29static int g_traceDurationSeconds = 5;
30static bool g_traceSchedSwitch = false;
31static bool g_traceCpuFrequency = false;
32static bool g_traceGovernorLoad = false;
33static bool g_traceWorkqueue = false;
34static bool g_traceOverwrite = false;
35static int g_traceBufferSizeKB = 2048;
36static bool g_compress = false;
37
38/* Global state */
39static bool g_traceAborted = false;
40
41/* Sys file paths */
42static const char* k_traceClockPath =
43    "/sys/kernel/debug/tracing/trace_clock";
44
45static const char* k_traceBufferSizePath =
46    "/sys/kernel/debug/tracing/buffer_size_kb";
47
48static const char* k_tracingOverwriteEnablePath =
49    "/sys/kernel/debug/tracing/options/overwrite";
50
51static const char* k_schedSwitchEnablePath =
52    "/sys/kernel/debug/tracing/events/sched/sched_switch/enable";
53
54static const char* k_cpuFreqEnablePath =
55    "/sys/kernel/debug/tracing/events/power/cpu_frequency/enable";
56
57static const char* k_governorLoadEnablePath =
58    "/sys/kernel/debug/tracing/events/cpufreq_interactive/enable";
59
60static const char* k_workqueueEnablePath =
61    "/sys/kernel/debug/tracing/events/workqueue/enable";
62
63static const char* k_tracingOnPath =
64    "/sys/kernel/debug/tracing/tracing_on";
65
66static const char* k_tracePath =
67    "/sys/kernel/debug/tracing/trace";
68
69static const char* k_traceMarkerPath =
70    "/sys/kernel/debug/tracing/trace_marker";
71
72// Write a string to a file, returning true if the write was successful.
73bool writeStr(const char* filename, const char* str)
74{
75    int fd = open(filename, O_WRONLY);
76    if (fd == -1) {
77        fprintf(stderr, "error opening %s: %s (%d)\n", filename,
78                strerror(errno), errno);
79        return false;
80    }
81
82    bool ok = true;
83    ssize_t len = strlen(str);
84    if (write(fd, str, len) != len) {
85        fprintf(stderr, "error writing to %s: %s (%d)\n", filename,
86                strerror(errno), errno);
87        ok = false;
88    }
89
90    close(fd);
91
92    return ok;
93}
94
95// Enable or disable a kernel option by writing a "1" or a "0" into a /sys file.
96static bool setKernelOptionEnable(const char* filename, bool enable)
97{
98    return writeStr(filename, enable ? "1" : "0");
99}
100
101// Enable or disable overwriting of the kernel trace buffers.  Disabling this
102// will cause tracing to stop once the trace buffers have filled up.
103static bool setTraceOverwriteEnable(bool enable)
104{
105    return setKernelOptionEnable(k_tracingOverwriteEnablePath, enable);
106}
107
108// Enable or disable tracing of the kernel scheduler switching.
109static bool setSchedSwitchTracingEnable(bool enable)
110{
111    return setKernelOptionEnable(k_schedSwitchEnablePath, enable);
112}
113
114// Enable or disable tracing of the CPU clock frequency.
115static bool setCpuFrequencyTracingEnable(bool enable)
116{
117    return setKernelOptionEnable(k_cpuFreqEnablePath, enable);
118}
119
120// Enable or disable tracing of the interactive CPU frequency governor's idea of
121// the CPU load.
122static bool setGovernorLoadTracingEnable(bool enable)
123{
124    return setKernelOptionEnable(k_governorLoadEnablePath, enable);
125}
126
127// Enable or disable tracing of the kernel workqueues.
128static bool setWorkqueueTracingEnabled(bool enable)
129{
130    return setKernelOptionEnable(k_workqueueEnablePath, enable);
131}
132
133// Enable or disable kernel tracing.
134static bool setTracingEnabled(bool enable)
135{
136    return setKernelOptionEnable(k_tracingOnPath, enable);
137}
138
139// Clear the contents of the kernel trace.
140static bool clearTrace()
141{
142    int traceFD = creat(k_tracePath, 0);
143    if (traceFD == -1) {
144        fprintf(stderr, "error truncating %s: %s (%d)\n", k_tracePath,
145                strerror(errno), errno);
146        return false;
147    }
148
149    close(traceFD);
150
151    return true;
152}
153
154// Set the size of the kernel's trace buffer in kilobytes.
155static bool setTraceBufferSizeKB(int size)
156{
157    char str[32] = "1";
158    int len;
159    if (size < 1) {
160        size = 1;
161    }
162    snprintf(str, 32, "%d", size);
163    return writeStr(k_traceBufferSizePath, str);
164}
165
166// Enable or disable the kernel's use of the global clock.  Disabling the global
167// clock will result in the kernel using a per-CPU local clock.
168static bool setGlobalClockEnable(bool enable)
169{
170    return writeStr(k_traceClockPath, enable ? "global" : "local");
171}
172
173// Check whether a file exists.
174static bool fileExists(const char* filename) {
175    return access(filename, F_OK) != -1;
176}
177
178// Enable tracing in the kernel.
179static bool startTrace()
180{
181    bool ok = true;
182
183    // Set up the tracing options.
184    ok &= setTraceOverwriteEnable(g_traceOverwrite);
185    ok &= setSchedSwitchTracingEnable(g_traceSchedSwitch);
186    ok &= setCpuFrequencyTracingEnable(g_traceCpuFrequency);
187    if (fileExists(k_governorLoadEnablePath) || g_traceGovernorLoad) {
188        ok &= setGovernorLoadTracingEnable(g_traceGovernorLoad);
189    }
190    ok &= setWorkqueueTracingEnabled(g_traceWorkqueue);
191    ok &= setTraceBufferSizeKB(g_traceBufferSizeKB);
192    ok &= setGlobalClockEnable(true);
193
194    // Enable tracing.
195    ok &= setTracingEnabled(true);
196
197    if (!ok) {
198        fprintf(stderr, "error: unable to start trace\n");
199    }
200
201    return ok;
202}
203
204// Disable tracing in the kernel.
205static void stopTrace()
206{
207    // Disable tracing.
208    setTracingEnabled(false);
209
210    // Set the options back to their defaults.
211    setTraceOverwriteEnable(true);
212    setSchedSwitchTracingEnable(false);
213    setCpuFrequencyTracingEnable(false);
214    if (fileExists(k_governorLoadEnablePath)) {
215        setGovernorLoadTracingEnable(false);
216    }
217    setWorkqueueTracingEnabled(false);
218    setGlobalClockEnable(false);
219
220    // Note that we can't reset the trace buffer size here because that would
221    // clear the trace before we've read it.
222}
223
224// Read the current kernel trace and write it to stdout.
225static void dumpTrace()
226{
227    int traceFD = open(k_tracePath, O_RDWR);
228    if (traceFD == -1) {
229        fprintf(stderr, "error opening %s: %s (%d)\n", k_tracePath,
230                strerror(errno), errno);
231        return;
232    }
233
234    if (g_compress) {
235        z_stream zs;
236        uint8_t *in, *out;
237        int result, flush;
238
239        bzero(&zs, sizeof(zs));
240        result = deflateInit(&zs, Z_DEFAULT_COMPRESSION);
241        if (result != Z_OK) {
242            fprintf(stderr, "error initializing zlib: %d\n", result);
243            close(traceFD);
244            return;
245        }
246
247        const size_t bufSize = 64*1024;
248        in = (uint8_t*)malloc(bufSize);
249        out = (uint8_t*)malloc(bufSize);
250        flush = Z_NO_FLUSH;
251
252        zs.next_out = out;
253        zs.avail_out = bufSize;
254
255        do {
256
257            if (zs.avail_in == 0) {
258                // More input is needed.
259                result = read(traceFD, in, bufSize);
260                if (result < 0) {
261                    fprintf(stderr, "error reading trace: %s (%d)\n",
262                            strerror(errno), errno);
263                    result = Z_STREAM_END;
264                    break;
265                } else if (result == 0) {
266                    flush = Z_FINISH;
267                } else {
268                    zs.next_in = in;
269                    zs.avail_in = result;
270                }
271            }
272
273            if (zs.avail_out == 0) {
274                // Need to write the output.
275                result = write(STDOUT_FILENO, out, bufSize);
276                if ((size_t)result < bufSize) {
277                    fprintf(stderr, "error writing deflated trace: %s (%d)\n",
278                            strerror(errno), errno);
279                    result = Z_STREAM_END; // skip deflate error message
280                    zs.avail_out = bufSize; // skip the final write
281                    break;
282                }
283                zs.next_out = out;
284                zs.avail_out = bufSize;
285            }
286
287        } while ((result = deflate(&zs, flush)) == Z_OK);
288
289        if (result != Z_STREAM_END) {
290            fprintf(stderr, "error deflating trace: %s\n", zs.msg);
291        }
292
293        if (zs.avail_out < bufSize) {
294            size_t bytes = bufSize - zs.avail_out;
295            result = write(STDOUT_FILENO, out, bytes);
296            if ((size_t)result < bytes) {
297                fprintf(stderr, "error writing deflated trace: %s (%d)\n",
298                        strerror(errno), errno);
299            }
300        }
301
302        result = deflateEnd(&zs);
303        if (result != Z_OK) {
304            fprintf(stderr, "error cleaning up zlib: %d\n", result);
305        }
306
307        free(in);
308        free(out);
309    } else {
310        ssize_t sent = 0;
311        while ((sent = sendfile(STDOUT_FILENO, traceFD, NULL, 64*1024*1024)) > 0);
312        if (sent == -1) {
313            fprintf(stderr, "error dumping trace: %s (%d)\n", strerror(errno),
314                    errno);
315        }
316    }
317
318    close(traceFD);
319}
320
321// Print the command usage help to stderr.
322static void showHelp(const char *cmd)
323{
324    fprintf(stderr, "usage: %s [options]\n", cmd);
325    fprintf(stderr, "options include:\n"
326                    "  -b N            use a trace buffer size of N KB\n"
327                    "  -c              trace into a circular buffer\n"
328                    "  -f              trace CPU frequency changes\n"
329                    "  -l              trace CPU frequency governor load\n"
330                    "  -s              trace the kernel scheduler switches\n"
331                    "  -t N            trace for N seconds [defualt 5]\n"
332                    "  -w              trace the kernel workqueue\n"
333                    "  -z              compress the trace dump\n");
334}
335
336static void handleSignal(int signo) {
337    g_traceAborted = true;
338}
339
340static void registerSigHandler() {
341    struct sigaction sa;
342    sigemptyset(&sa.sa_mask);
343    sa.sa_flags = 0;
344    sa.sa_handler = handleSignal;
345    sigaction(SIGHUP, &sa, NULL);
346    sigaction(SIGINT, &sa, NULL);
347    sigaction(SIGQUIT, &sa, NULL);
348    sigaction(SIGTERM, &sa, NULL);
349}
350
351int main(int argc, char **argv)
352{
353    if (argc == 2 && 0 == strcmp(argv[1], "--help")) {
354        showHelp(argv[0]);
355        exit(0);
356    }
357
358    if (getuid() != 0) {
359        fprintf(stderr, "error: %s must be run as root.", argv[0]);
360        exit(1);
361    }
362
363    for (;;) {
364        int ret;
365
366        ret = getopt(argc, argv, "b:cflst:wz");
367
368        if (ret < 0) {
369            break;
370        }
371
372        switch(ret) {
373            case 'b':
374                g_traceBufferSizeKB = atoi(optarg);
375            break;
376
377            case 'c':
378                g_traceOverwrite = true;
379            break;
380
381            case 'l':
382                g_traceGovernorLoad = true;
383            break;
384
385            case 'f':
386                g_traceCpuFrequency = true;
387            break;
388
389            case 's':
390                g_traceSchedSwitch = true;
391            break;
392
393            case 't':
394                g_traceDurationSeconds = atoi(optarg);
395            break;
396
397            case 'w':
398                g_traceWorkqueue = true;
399            break;
400
401            case 'z':
402                g_compress = true;
403            break;
404
405            default:
406                fprintf(stderr, "\n");
407                showHelp(argv[0]);
408                exit(-1);
409            break;
410        }
411    }
412
413    registerSigHandler();
414
415    bool ok = startTrace();
416
417    if (ok) {
418        printf("capturing trace...");
419        fflush(stdout);
420
421        // We clear the trace after starting it because tracing gets enabled for
422        // each CPU individually in the kernel. Having the beginning of the trace
423        // contain entries from only one CPU can cause "begin" entries without a
424        // matching "end" entry to show up if a task gets migrated from one CPU to
425        // another.
426        ok = clearTrace();
427
428        if (ok) {
429            // Sleep to allow the trace to be captured.
430            struct timespec timeLeft;
431            timeLeft.tv_sec = g_traceDurationSeconds;
432            timeLeft.tv_nsec = 0;
433            do {
434                if (g_traceAborted) {
435                    break;
436                }
437            } while (nanosleep(&timeLeft, &timeLeft) == -1 && errno == EINTR);
438        }
439    }
440
441    // Stop the trace and restore the default settings.
442    stopTrace();
443
444    if (ok) {
445        if (!g_traceAborted) {
446            printf(" done\nTRACE:\n");
447            fflush(stdout);
448            dumpTrace();
449        } else {
450            printf("\ntrace aborted.\n");
451            fflush(stdout);
452        }
453        clearTrace();
454    } else {
455        fprintf(stderr, "unable to start tracing\n");
456    }
457
458    // Reset the trace buffer size to 1.
459    setTraceBufferSizeKB(1);
460
461    return g_traceAborted ? 1 : 0;
462}
463