trace-cmd: Add trace-cmd record --date option

Adding the --date option to trace-cmd record (and extract) will
cause trace-cmd to write a timestamp into the ftrace buffer and
use it to mapped the ftrace buffer's timestamps with gettimeofday.

This will allow reading of the trace.dat file to be able to convert
the timestamps into actual wall time.

Signed-off-by: Steven Rostedt <rostedt@goodmis.org>

2 files changed, 283 insertions, 11 deletions

diff --git a/Documentation/trace-cmd-record.1.txt b/Documentation/trace-cmd-record.1.txt
index 0954540..2ae6748 100644
--- a/Documentation/trace-cmd-record.1.txt
+++ b/Documentation/trace-cmd-record.1.txt
@@ -177,6 +177,11 @@ OPTIONS
     reliable, the amount of data is not that intensive, and a guarantee is
     needed that all traced information is transfered successfully.
 
+*--date*::
+    With the *--date* option, "trace-cmd" will write timestamps into the
+    trace buffer after it has finished recording. It will then map the
+    timestamp to gettimeofday which will allow wall time output from the
+    timestamps reading the created 'trace.dat' file.
 
 EXAMPLES
 --------
diff --git a/trace-record.c b/trace-record.c
index 0d6b38a..52d9fd8 100644
--- a/trace-record.c
+++ b/trace-record.c
@@ -25,8 +25,10 @@
 #include <stdlib.h>
 #include <string.h>
 #include <stdarg.h>
+#include <getopt.h>
 #include <sys/types.h>
 #include <sys/stat.h>
+#include <sys/time.h>
 #include <sys/wait.h>
 #include <sys/socket.h>
 #include <sys/ptrace.h>
@@ -51,6 +53,7 @@
 #define CURRENT         "current_tracer"
 #define ITER_CTRL       "trace_options"
 #define MAX_LATENCY     "tracing_max_latency"
+#define STAMP           "stamp"
 
 #define UDP_MAX_PACKET (65536 - 20)
 
@@ -82,6 +85,9 @@ static int filter_pid = -1;
 
 static int finished;
 
+/* Try a few times to get an accurate date */
+static int date2ts_tries = 5;
+
 struct func_list {
         struct func_list *next;
         const char *func;
@@ -1337,8 +1343,6 @@ static void setup_network(void)
         write(sfd, buf, strlen(buf)+1);
 
         /* write the pagesize (in ASCII) */
-
-        page_size = getpagesize();
         sprintf(buf, "%d", page_size);
 
         /* include \0 */
@@ -1417,7 +1421,7 @@ static void start_threads(void)
         }
 }
 
-static void record_data(void)
+static void record_data(char *date2ts)
 {
         struct tracecmd_output *handle;
         char **temp_files;
@@ -1439,8 +1443,15 @@ static void record_data(void)
                 for (i = 0; i < cpu_count; i++)
                         temp_files[i] = get_temp_file(i);
 
-                handle = tracecmd_create_file_glob(output_file, cpu_count,
-                                                   temp_files, listed_events);
+                handle = tracecmd_create_init_file_glob(output_file, listed_events);
+                if (!handle)
+                        die("Error creating output file");
+
+                if (date2ts)
+                        tracecmd_add_option(handle, TRACECMD_OPTION_DATE,
+                                            strlen(date2ts)+1, date2ts);
+
+                tracecmd_append_cpu_data(handle, cpu_count, temp_files);
 
                 for (i = 0; i < cpu_count; i++)
                         put_temp_file(temp_files[i]);
@@ -1531,6 +1542,232 @@ static void add_func(struct func_list **list, const char *func)
         *list = item;
 }
 
+static unsigned long long
+find_ts_in_page(struct pevent *pevent, void *page, int size)
+{
+        struct event_format *event;
+        struct format_field *field;
+        struct record *last_record = NULL;
+        struct record *record;
+        unsigned long long ts = 0;
+        int id;
+
+        if (size <= 0)
+                return 0;
+
+        while (!ts) {
+                record = tracecmd_read_page_record(pevent, page, size,
+                                                   last_record);
+                if (!record)
+                        break;
+                free_record(last_record);
+                id = pevent_data_type(pevent, record);
+                event = pevent_data_event_from_type(pevent, id);
+                if (event) {
+                        /* Make sure this is our event */
+                        field = pevent_find_field(event, "buf");
+                        /* the trace_marker adds a '\n' */
+                        if (field && strcmp(STAMP"\n", record->data + field->offset) == 0)
+                                ts = record->ts;
+                }
+                last_record = record;
+        }
+        free_record(last_record);
+
+        return ts;
+}
+
+static unsigned long long find_time_stamp(struct pevent *pevent)
+{
+        struct dirent *dent;
+        unsigned long long ts = 0;
+        void *page;
+        char *path;
+        char *file;
+        DIR *dir;
+        int len;
+        int fd;
+        int r;
+
+        path = tracecmd_get_tracing_file("per_cpu");
+        if (!path)
+                return 0;
+
+        dir = opendir(path);
+        if (!dir)
+                goto out;
+
+        len = strlen(path);
+        file = malloc_or_die(len + strlen("trace_pipe_raw") + 32);
+        page = malloc_or_die(page_size);
+
+        while ((dent = readdir(dir))) {
+                const char *name = dent->d_name;
+
+                if (strncmp(name, "cpu", 3) != 0)
+                        continue;
+
+                sprintf(file, "%s/%s/trace_pipe_raw", path, name);
+                fd = open(file, O_RDONLY);
+                if (fd < 0)
+                        continue;
+                do {
+                        r = read(fd, page, page_size);
+                        ts = find_ts_in_page(pevent, page, r);
+                        if (ts)
+                                break;
+                } while (r > 0);
+                if (ts)
+                        break;
+        }
+        free(file);
+        free(page);
+        closedir(dir);
+
+ out:
+        tracecmd_put_tracing_file(path);
+        return ts;
+}
+
+static char *read_file(char *file, int *psize)
+{
+        char buffer[BUFSIZ];
+        char *path;
+        char *buf;
+        int size = 0;
+        int fd;
+        int r;
+
+        path = tracecmd_get_tracing_file(file);
+        fd = open(path, O_RDONLY);
+        tracecmd_put_tracing_file(path);
+        if (fd < 0) {
+                warning("%s not found, --date ignored", file);
+                return NULL;
+        }
+        do {
+                r = read(fd, buffer, BUFSIZ);
+                if (r <= 0)
+                        continue;
+                if (size) {
+                        buf = realloc(buf, size+r);
+                        if (!buf)
+                                die("malloc");
+                } else
+                        buf = malloc_or_die(r);
+                memcpy(buf+size, buffer, r);
+                size += r;
+        } while (r);
+
+        *psize = size;
+        return buf;
+}
+
+/*
+ * Try to write the date into the ftrace buffer and then
+ * read it back, mapping the timestamp to the date.
+ */
+static char *get_date_to_ts(void)
+{
+        unsigned long long min = -1ULL;
+        unsigned long long diff;
+        unsigned long long stamp;
+        unsigned long long min_stamp;
+        unsigned long long min_ts;
+        unsigned long long ts;
+        struct pevent *pevent;
+        struct timeval start;
+        struct timeval end;
+        char *date2ts = NULL;
+        char *path;
+        char *buf;
+        int size;
+        int tfd;
+        int ret;
+        int i;
+
+        /* Set up a pevent to read the raw format */
+        pevent = pevent_alloc();
+        if (!pevent) {
+                warning("failed to alloc pevent, --date ignored");
+                return NULL;
+        }
+
+        buf = read_file("events/header_page", &size);
+        if (!buf)
+                goto out_pevent;
+        ret = pevent_parse_header_page(pevent, buf, size, sizeof(unsigned long));
+        free(buf);
+        if (ret < 0) {
+                warning("Can't parse header page, --date ignored");
+                goto out_pevent;
+        }
+
+        /* Find the format for ftrace:print. */
+        buf = read_file("events/ftrace/print/format", &size);
+        if (!buf)
+                goto out_pevent;
+        ret = pevent_parse_event(pevent, buf, size, "ftrace");
+        free(buf);
+        if (ret < 0) {
+                warning("Can't parse print event, --date ignored");
+                goto out_pevent;
+        }
+
+        path = tracecmd_get_tracing_file("trace_marker");
+        tfd = open(path, O_WRONLY);
+        tracecmd_put_tracing_file(path);
+        if (tfd < 0) {
+                warning("Can not open 'trace_marker', --date ignored");
+                goto out_pevent;
+        }
+
+        for (i = 0; i < date2ts_tries; i++) {
+                disable_tracing();
+                clear_trace();
+                enable_tracing();
+
+                gettimeofday(&start, NULL);
+                write(tfd, STAMP, 5);
+                gettimeofday(&end, NULL);
+
+                disable_tracing();
+                ts = find_time_stamp(pevent);
+                if (!ts)
+                        continue;
+
+                diff = (unsigned long long)end.tv_sec * 1000000;
+                diff += (unsigned long long)end.tv_usec;
+                stamp = diff;
+                diff -= (unsigned long long)start.tv_sec * 1000000;
+                diff -= (unsigned long long)start.tv_usec;
+
+                if (diff < min) {
+                        min_ts = ts;
+                        min_stamp = stamp - diff / 2;
+                        min = diff;
+                }
+        }
+
+        close(tfd);
+
+        /* 16 hex chars + 0x + \0 */
+        date2ts = malloc(19);
+        if (!date2ts)
+                goto out_pevent;
+
+        /*
+         * The difference between the timestamp and the gtod is
+         * stored as an ASCII string in hex.
+         */
+        snprintf(date2ts, 19, "0x%llx", min_stamp - min_ts / 1000);
+
+ out_pevent:
+        pevent_free(pevent);
+
+        return date2ts;
+}
+
 void set_buffer_size(void)
 {
         char buf[BUFSIZ];
@@ -1566,6 +1803,7 @@ void trace_record (int argc, char **argv)
         struct event_list *last_event;
         struct tracecmd_event_list *list;
         struct trace_seq s;
+        char *date2ts = NULL;
         int record_all = 0;
         int disable = 0;
         int events = 0;
@@ -1606,7 +1844,18 @@ void trace_record (int argc, char **argv)
         } else
                 usage(argv);
 
-        while ((c = getopt(argc-1, argv+1, "+hae:f:Fp:cdo:O:s:r:vg:l:n:P:N:tb:ki")) >= 0) {
+        for (;;) {
+                int option_index = 0;
+                static struct option long_options[] = {
+                        {"date", no_argument, NULL, 0},
+                        {"help", no_argument, NULL, '?'},
+                        {NULL, 0, NULL, 0}
+                };
+
+                c = getopt_long (argc-1, argv+1, "+hae:f:Fp:cdo:O:s:r:vg:l:n:P:N:tb:ki",
+                                 long_options, &option_index);
+                if (c == -1)
+                        break;
                 switch (c) {
                 case 'h':
                         usage(argv);
@@ -1746,6 +1995,17 @@ void trace_record (int argc, char **argv)
                 case 'i':
                         ignore_event_not_found = 1;
                         break;
+                case 0:
+                        switch (option_index) {
+                        case 0: /* date */
+                                date = 1;
+                                break;
+                        default:
+                                usage(argv);
+                        }
+                        break;
+                default:
+                        usage(argv);
                 }
         }
 
@@ -1773,6 +2033,8 @@ void trace_record (int argc, char **argv)
         if (event_selection)
                 expand_event_list();
 
+        page_size = getpagesize();
+
         if (!extract) {
                 fset = set_ftrace(!disable);
                 disable_all();
@@ -1841,8 +2103,9 @@ void trace_record (int argc, char **argv)
 
         stop_threads();
 
-        record_data();
-        delete_thread_data();
+
+        if (!keep)
+                disable_all();
 
         printf("Kernel buffer statistics:\n"
                "  Note: \"entries\" are the entries left in the kernel ring buffer and are not\n"
@@ -1856,12 +2119,16 @@ void trace_record (int argc, char **argv)
                 printf("\n");
         }
 
+        if (date)
+                date2ts = get_date_to_ts();
+
+        record_data(date2ts);
+        delete_thread_data();
+
+
         if (keep)
                 exit(0);
 
-        /* Turn off everything */
-        disable_all();
-
         /* If tracing_on was enabled before we started, set it on now */
         if (tracing_on_init_val)
                 write_tracing_on(tracing_on_init_val);