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