instruments/poller: add ftrace marker support

- Add an option to the poller binary insert a marker into ftrace that
  aligns with the first output entry. The option is exposed as an
  instrument parameter.
- If this parameter is set, the resulting .csv will be post-processed to
  update the timestamps to align with trace-cmd output.
- Change poller artifact names to use - instead of _ to be consistent
  with trace-cmd artifact naming.

wa/instruments/poller/__init__.py

@@ -14,8 +14,12 @@
 # pylint: disable=access-member-before-definition,attribute-defined-outside-init,unused-argument
 import os
 
+import pandas as pd
+
 from wa import Instrument, Parameter, Executable
+from wa.framework import signal
 from wa.framework.exception import ConfigError, InstrumentError
+from wa.utils.trace_cmd import TraceCmdParser
 from wa.utils.types import list_or_string
 
 
@@ -38,9 +42,18 @@ class FilePoller(Instrument):
         Parameter('files', kind=list_or_string, mandatory=True,
                   description="""A list of paths to the files to be polled"""),
         Parameter('labels', kind=list_or_string,
-                  description="""A list of lables to be used in the CSV output for
+                  description="""
-                                 the corresponding files. This cannot be used if
+                  A list of lables to be used in the CSV output for the
-                                 a `*` wildcard is used in a path."""),
+                  corresponding files. This cannot be used if a `*` wildcard is
+                  used in a path.
+                  """),
+        Parameter('align_with_ftrace', kind=bool, default=False,
+                  description="""
+                  Insert a marker into ftrace that aligns with the first
+                  timestamp. During output processing, extract the marker
+                  and use it's timestamp to adjust the timestamps in the collected
+                  csv so that they align with ftrace.
+                  """),
         Parameter('as_root', kind=bool, default=False,
                   description="""
                   Whether or not the poller will be run as root. This should be
@@ -74,12 +87,17 @@ class FilePoller(Instrument):
 
         self.target_output_path = self.target.path.join(self.target.working_directory, 'poller.csv')
         self.target_log_path = self.target.path.join(self.target.working_directory, 'poller.log')
-        self.command = '{} -t {} -l {} {} > {} 2>{}'.format(target_poller,
+        marker_option = ''
-                                                            self.sample_interval * 1000,
+        if self.align_with_ftrace:
-                                                            ','.join(self.labels),
+            marker_option = '-m'
-                                                            ' '.join(self.files),
+            signal.connect(self._adjust_timestamps, signal.AFTER_JOB_OUTPUT_PROCESSED)
-                                                            self.target_output_path,
+        self.command = '{} -t {} {} -l {} {} > {} 2>{}'.format(target_poller,
-                                                            self.target_log_path)
+                                                               self.sample_interval * 1000,
+                                                               marker_option,
+                                                               ','.join(self.labels),
+                                                               ' '.join(self.files),
+                                                               self.target_output_path,
+                                                               self.target_log_path)
 
     def start(self, context):
         self.target.kick_off(self.command, as_root=self.as_root)
@@ -90,10 +108,11 @@ class FilePoller(Instrument):
     def update_output(self, context):
         host_output_file = os.path.join(context.output_directory, 'poller.csv')
         self.target.pull(self.target_output_path, host_output_file)
-        context.add_artifact('poller_output', host_output_file, kind='data')
+        context.add_artifact('poller-output', host_output_file, kind='data')
+
         host_log_file = os.path.join(context.output_directory, 'poller.log')
         self.target.pull(self.target_log_path, host_log_file)
-        context.add_artifact('poller_log', host_log_file, kind='log')
+        context.add_artifact('poller-log', host_log_file, kind='log')
 
         with open(host_log_file) as fh:
             for line in fh:
@@ -120,3 +139,24 @@ class FilePoller(Instrument):
             label_parts.append(pp[-1])  # always use file name even if same for all
             labels.append('-'.join(label_parts))
         return labels
+
+    def _adjust_timestamps(self, context):
+        output_file = context.get_artifact_path('poller-output')
+        message = 'Adjusting timestamps inside "{}" to align with ftrace'
+        self.logger.debug(message.format(output_file))
+
+        trace_txt = context.get_artifact_path('trace-cmd-txt')
+        trace_parser = TraceCmdParser(filter_markers=False)
+        marker_timestamp = None
+        for event in trace_parser.parse(trace_txt):
+            if event.name == 'print' and 'POLLER_START' in event.text:
+                marker_timestamp = event.timestamp
+                break
+
+        if marker_timestamp is None:
+            raise InstrumentError('Did not see poller marker in ftrace')
+
+        df = pd.read_csv(output_file)
+        df.time -= df.time[0]
+        df.time += marker_timestamp
+        df.to_csv(output_file, index=False)

wa/instruments/poller/poller.c

@@ -1,7 +1,7 @@
 #include <fcntl.h>
 #include <stdio.h>
 #include <sys/poll.h>
-#include <sys/time.h>
+#include <time.h>
 #include <unistd.h>
 #include <errno.h>
 #include <signal.h>
@@ -31,6 +31,23 @@ typedef struct {
         char *path;
 } poll_source_t;
 
+
+int write_trace_marker(char *marker, int size)
+{
+        int ret;
+        FILE *file;
+
+        file = fopen("/sys/kernel/debug/tracing/trace_marker", "w");
+        if (file == NULL) {
+                return -errno;
+        }
+
+        ret = fwrite(marker, sizeof(char), size, file);
+
+        fclose(file);
+        return ret;
+}
+
 int main(int argc, char ** argv) {
 
     extern char *optarg;
@@ -40,16 +57,21 @@ int main(int argc, char ** argv) {
     useconds_t interval = 1000000;
     char buf[1024];
     memset(buf, 0, sizeof(buf));
-    struct timeval current_time;
+    struct timespec current_time;
     double time_float;
     char *labels;
     int labelCount = 0;
+    int should_write_marker = 0;
+    int ret;
 
-    static char usage[] = "usage: %s [-h] [-t INTERVAL] FILE [FILE ...]\n"
+    static char usage[] = "usage: %s [-h] [-m] [-t INTERVAL] FILE [FILE ...]\n"
                           "polls FILE(s) every INTERVAL microseconds and outputs\n"
                           "the results in CSV format including a timestamp to STDOUT\n"
                           "\n"
                           "    -h     Display this message\n"
+                          "    -m     Insert a marker into ftrace at the time of the first\n"
+                          "           sample. This marker may be used to align the timestamps\n"
+                          "           produced by the poller with those of ftrace events.\n"
                           "    -t     The polling sample interval in microseconds\n"
                           "           Defaults to 1000000 (1 second)\n"
                           "    -l     Comma separated list of labels to use in the CSV\n"
@@ -57,7 +79,7 @@ int main(int argc, char ** argv) {
 
 
     //Handling command line arguments
-    while ((c = getopt(argc, argv, "ht:l:")) != -1)
+    while ((c = getopt(argc, argv, "hmt:l:")) != -1)
     {
         switch(c) {
             case 'h':
@@ -65,6 +87,9 @@ int main(int argc, char ** argv) {
             default:
                 show_help = 1;
                 break;
+            case 'm':
+                should_write_marker = 1;
+		break;
             case 't':
                 interval = (useconds_t)atoi(optarg);
                 break;
@@ -131,9 +156,17 @@ int main(int argc, char ** argv) {
     //Poll files 
     int bytes_read = 0;
     while (!done) {
-        gettimeofday(&current_time, NULL);
+        clock_gettime(CLOCK_BOOTTIME, &current_time);
+        if (should_write_marker) {
+            ret = write_trace_marker("POLLER_START", 12);
+            if (ret < 0) {
+                fprintf(stderr, "ERROR writing trace marker: %s\n", strerror(ret));
+                exit(ret);
+            }
+        }
+
         time_float = (double)current_time.tv_sec;
-        time_float += ((double)current_time.tv_usec)/1000/1000;
+        time_float += ((double)current_time.tv_nsec)/1000/1000/1000;
         printf("%f", time_float);
         for (i = 0; i < num_files; i++) {
             lseek(files_to_poll[i].fd, 0, SEEK_SET);