rt-graph: real-time plots display info popup

When you hover close enough to an events time, the event name will
display. This time is based on _litmus_ time, not record time.

8 files changed, 239 insertions, 40 deletions

diff --git a/Documentation/structure.txt b/Documentation/structure.txt
index adee54d..4060c51 100644
--- a/Documentation/structure.txt
+++ b/Documentation/structure.txt
@@ -99,6 +99,7 @@ struct trace-plot-task.c {
 
   /* Return first record after time which is from our pid */
   find_record(ginfo, pid, time);
+    - set_cpus_to_time
 
   /* Updates last_whatevers in task info */
   update_last_record(ginfo, task_plot_info, record);
@@ -107,6 +108,9 @@ struct trace-plot-task.c {
   find_previous_record(ginfo, start_record, pid, cpu);
 
   get_display_record(ginfo, pid, time);
+    - find_record
+    - find_previous_record
+
 
   /**** PUBLIC METHODS *****/
 
@@ -119,6 +123,19 @@ struct trace-plot-task.c {
   /* Get record at time, print info */
   task_plot_display_last_event(info, plot, trace_seq s, time);
 
+  /* Just frontend for find_record */
+  task_plot_find_record(ginfo, plot, time);
+
+  /* Print out event info if in current resolution */
+  task_plot_display_info(ginfo, plot, sequence s, time);
+   - get_display_record
+     - find_record
+       - set_cpus_to_time
+     - find_previous_record
+
+  /* Free private info */
+  task_plot_destroy(info, plot);
+
   /* Always draws a line of the color of the pid. Always.
    * Then update_last_record.
    * If record is null, times up, just finish our shit and return.
@@ -141,15 +158,6 @@ struct trace-plot-task.c {
    */
   task_plot_event(ginfo, plot,r ecord, info);
 
-  /* Just frontend for find_record */
-  task_plot_find_record(ginfo, plot, time);
-
-  /* Print out event info if in current resolution */
-  task_plot_display_info(ginfo, plot, sequence s, time);
-
-  /* Free private info */
-  task_plot_destroy(info, plot);
-
 
   /*** STATIC METHODS ***/
 
diff --git a/parse-events.h b/parse-events.h
index 56cef4a..83c7d79 100644
--- a/parse-events.h
+++ b/parse-events.h
@@ -42,6 +42,7 @@
 struct record {
         unsigned long long      ts;
         unsigned long long      offset;
+        unsigned long long      cached_rts;
         long long               missed_events;  /* buffer dropped events before */
         int                     record_size;    /* size of binary record */
         int                     size;           /* size of data */
diff --git a/rt-graph.c b/rt-graph.c
index 5b8c759..5f4d0b0 100644
--- a/rt-graph.c
+++ b/rt-graph.c
@@ -121,7 +121,6 @@ int rt_graph_check_task_param(struct rt_graph_info *rtinfo,
                 dprintf(3, "Read task_param (%d) record for task %d "
                         "(%llu, %llu)\n", id, *pid, *wcet, *period);
 
-                /* Only of these per task, so we can safely add new tasks now */
                 add_task_hash(rtinfo->tasks, *pid);
         }
  out:
diff --git a/rt-graph.h b/rt-graph.h
index be9aa44..17247f6 100644
--- a/rt-graph.h
+++ b/rt-graph.h
@@ -7,7 +7,7 @@
 #include "rt-plot-task.h"
 
 #define RT_TS_FIELD "__rt_ts"
-#define TS_HASH_SIZE 6
+#define TS_HASH_SIZE 12
 struct ts_list;
 
 struct rt_graph_info {
@@ -52,7 +52,7 @@ struct rt_graph_info {
         struct format_field     *resume_pid_field;
         struct format_field     *resume_ts_field;
 
-        /* Cache of ts fields for new events */
+        /* Cache of ts fields for non-litmus events */
         struct ts_list          *events[TS_HASH_SIZE];
 };
 
diff --git a/rt-plot-task.c b/rt-plot-task.c
index 8be1888..8ecbdbb 100644
--- a/rt-plot-task.c
+++ b/rt-plot-task.c
@@ -13,7 +13,159 @@
 #define dprintf(l, x...)        do { if (0) printf(x); } while (0)
 #endif
 
-/* Ok to do it this way as long as it remains single threaded */
+/*
+ * Extract timestamp from a record, attempting to use cache if possible
+ */
+static unsigned long long
+get_rts(struct graph_info *ginfo, struct record *record)
+{
+        gint epid;
+        unsigned long long ts;
+        if (!record->cached_rts) {
+                rt_graph_check_any(&ginfo->rtinfo, ginfo->pevent, record,
+                                   &epid, &ts);
+                record->cached_rts = ts;
+        } else
+                ts = record->cached_rts;
+        return ts;
+}
+
+/*
+ * Get the real-time timestamp of the next record at time
+ */
+static unsigned long long
+next_rts(struct graph_info *ginfo, int cpu, unsigned long long time)
+{
+        struct record *record;
+        unsigned long long ts;
+        tracecmd_set_cpu_to_timestamp(ginfo->handle, cpu, time);
+        record = tracecmd_read_data(ginfo->handle, cpu);
+        if (record) {
+                ts = get_rts(ginfo, record);
+                free_record(record);
+                return ts;
+        } else
+                return 0;
+}
+
+static void set_cpu_to_time(int cpu, struct graph_info *ginfo, unsigned long long time)
+{
+        struct record *record;
+        unsigned long long rts, seek_time, last_seek;
+        long long diff;
+
+        rts = next_rts(ginfo, cpu, time);
+        diff = time - rts;
+
+        /* "Guess" a new target based on difference */
+        seek_time = time + diff;
+        rts = next_rts(ginfo, cpu, seek_time);
+        diff = time - rts;
+
+        /* Zero in in 1.5x the difference increments */
+        if (rts && diff > 0) {
+                /*   rts       time
+                 *   seek        ?
+                 * ---|---->>----|---
+                 */
+                do {
+                        last_seek = seek_time;
+                        seek_time = seek_time + 1.5 * (time - rts);
+                        rts = next_rts(ginfo, cpu, seek_time);
+                } while (rts < time);
+                tracecmd_set_cpu_to_timestamp(ginfo->handle, cpu, last_seek);
+                seek_time = last_seek;
+        } else if (rts && diff < 0) {
+                /*   time      rts
+                 *    ?        seek
+                 * ---|----<<----|---
+                 */
+                do {
+                        seek_time = seek_time - 1.5 * (rts - time);
+                        rts = next_rts(ginfo, cpu, seek_time);
+                } while (rts > time);
+        }
+
+        /* Get to first record at or after time */
+        while ((record = tracecmd_read_data(ginfo->handle, cpu))) {
+                if (get_rts(ginfo, record) >= time)
+                        break;
+                free_record(record);
+        }
+        if (record) {
+                tracecmd_set_cursor(ginfo->handle, cpu, record->offset);
+                free_record(record);
+        } else
+                tracecmd_set_cpu_to_timestamp(ginfo->handle, cpu, seek_time);
+}
+
+void set_cpus_to_time(struct graph_info *ginfo, unsigned long long time)
+{
+        int cpu;
+        for (cpu = 0; cpu < ginfo->cpus; cpu++)
+                set_cpu_to_time(cpu, ginfo, time);
+}
+
+static gboolean record_matches_pid(struct graph_info *ginfo,
+                                   struct record *record,
+                                   int match_pid)
+{
+        guint eid, pid;
+        unsigned long long val;
+        struct format_field *pid_field = NULL;
+        struct rt_graph_info *rtinfo = &ginfo->rtinfo;
+
+        eid = pevent_data_type(ginfo->pevent, record);
+        if (eid == rtinfo->task_param_id)
+                pid_field = rtinfo->param_pid_field;
+        else if (eid == rtinfo->switch_to_id)
+                pid_field = rtinfo->switch_to_pid_field;
+        else if (eid == rtinfo->switch_away_id)
+                pid_field = rtinfo->switch_away_pid_field;
+        else if (eid == rtinfo->task_release_id)
+                pid_field = rtinfo->release_pid_field;
+        else if (eid == rtinfo->task_completion_id)
+                pid_field = rtinfo->completion_pid_field;
+        else if (eid == rtinfo->task_block_id)
+                pid_field = rtinfo->block_pid_field;
+        else if (eid == rtinfo->task_resume_id)
+                pid_field = rtinfo->resume_pid_field;
+
+        if (pid_field) {
+                pevent_read_number_field(rtinfo->param_pid_field,
+                                         record->data, &val);
+                pid = val;
+        } else {
+                pid = pevent_data_pid(ginfo->pevent, record);
+        }
+
+        if (pid == match_pid)
+                return TRUE;
+        else
+                return FALSE;
+}
+
+struct record*
+find_record(struct graph_info *ginfo, gint pid, guint64 time)
+{
+        int next_cpu, match;
+        struct record *record = NULL;
+
+        set_cpus_to_time(ginfo, time);
+        do {
+                free_record(record);
+                record = tracecmd_read_next_data(ginfo->handle, &next_cpu);
+                if (!record)
+                        return NULL;
+                match = record_matches_pid(ginfo, record, pid);
+        } while (!(get_rts(ginfo, record) > time && match));
+
+        return record;
+}
+
+/*
+ * Update current job in @rtt_info, ensuring monotonic increase
+ */
 static void update_job(struct rt_task_info *rtt_info, int job)
 {
         if (job < rtt_info->last_job) {
@@ -88,6 +240,9 @@ static int try_completion(struct graph_info *ginfo,
                 info->completion = TRUE;
                 info->ctime = ts;
                 info->clabel = rtt_info->label;
+                info->line = TRUE;
+                info->lcolor = hash_pid(record->cpu);
+                info->ltime = ts;
                 ret = 1;
         }
         return ret;
@@ -177,10 +332,6 @@ static int try_switch_to(struct graph_info *ginfo, struct rt_task_info *rtt_info
                 rtt_info->run_time = ts;
                 rtt_info->last_cpu = record->cpu;
 
-                info->line = TRUE;
-                info->lcolor = hash_pid(record->cpu);
-                info->ltime = ts;
-
                 dprintf(3, "Switching to %d:%d at %llu on CPU %d\n",
                         rtt_info->base.pid, rtt_info->last_job,
                         ts, rtt_info->last_cpu);
@@ -289,15 +440,65 @@ static void rt_task_plot_destroy(struct graph_info *ginfo, struct graph_plot *pl
         task_plot_destroy(ginfo, plot);
 }
 
+static int rt_task_plot_display_last_event(struct graph_info *ginfo,
+                                 struct graph_plot *plot,
+                                 struct trace_seq *s,
+                                 unsigned long long time)
+{
+        trace_seq_printf(s, "Displaying last event at %llu\n",
+                         time);
+        return 1;
+}
+
+static int rt_task_plot_display_info(struct graph_info *ginfo,
+                          struct graph_plot *plot,
+                          struct trace_seq *s,
+                          unsigned long long time)
+{
+        int type;
+        struct record *record;
+        struct event_format *event;
+        unsigned long sec, usec;
+        struct rt_task_info *rtt_info = plot->private;
+
+        record = find_record(ginfo, rtt_info->base.pid, time);
+        if (!record)
+                return 0;
+
+        /* Display only if the record's time is close enough */
+        if (get_rts(ginfo, record) > time - 2/ginfo->resolution &&
+            get_rts(ginfo, record) < time + 2/ginfo->resolution) {
+
+                type = pevent_data_type(ginfo->pevent, record);
+                event = pevent_data_event_from_type(ginfo->pevent, type);
+                if (event) {
+                        trace_seq_puts(s, event->name);
+                        trace_seq_putc(s, '\n');
+                        pevent_event_info(s, event, record);
+                        trace_seq_putc(s, '\n');
+                } else
+                        trace_seq_printf(s, "UNKNOWN EVENT %d\n", type);
+        }
+
+        /* Display a timestamp always */
+        convert_nano(get_rts(ginfo, record), &sec, &usec);
+        trace_seq_printf(s, "%lu.%06lu CPU: %03d",
+                         sec, usec, record->cpu);
+        free_record(record);
+
+        return 1;
+}
+
 static const struct plot_callbacks rt_task_cb = {
         .plot_event             = rt_task_plot_event,
         .start                  = rt_task_plot_start,
         .destroy                = rt_task_plot_destroy,
 
+        .display_last_event     = rt_task_plot_display_last_event,
+        .display_info           = rt_task_plot_display_info,
+
         .match_time             = task_plot_match_time,
-        .display_last_event     = task_plot_display_last_event,
         .find_record            = task_plot_find_record,
-        .display_info           = task_plot_display_info,
 };
 
 void rt_plot_task_update_callback(gboolean accept,
diff --git a/trace-input.c b/trace-input.c
index b6af1e6..5b01386 100644
--- a/trace-input.c
+++ b/trace-input.c
@@ -1625,6 +1625,7 @@ tracecmd_read_page_record(struct pevent *pevent, void *page, int size,
         record->cpu = 0;
         record->data = ptr;
         record->ref_count = 1;
+        record->cached_rts = 0ULL;
 
         return record;
 }
@@ -1745,6 +1746,7 @@ read_again:
         record->missed_events = missed_events;
         record->ref_count = 1;
         record->locked = 1;
+        record->cached_rts = 0ULL;
 
         ptr += length;
 
diff --git a/trace-plot-task.c b/trace-plot-task.c
index 068fd91..abcdd89 100644
--- a/trace-plot-task.c
+++ b/trace-plot-task.c
@@ -39,11 +39,11 @@ gboolean is_running(struct graph_info *ginfo, struct record *record)
         return val ? FALSE : TRUE;
 }
 
-gboolean record_matches_pid(struct graph_info *ginfo,
-                            struct record *record, int match_pid,
-                            int *pid, int *sched_pid,
-                            gboolean *is_sched,
-                            gboolean *wakeup)
+static gboolean record_matches_pid(struct graph_info *ginfo,
+                                   struct record *record, int match_pid,
+                                   int *pid, int *sched_pid,
+                                   gboolean *is_sched,
+                                   gboolean *wakeup)
 {
         const char *comm;
 
@@ -73,7 +73,7 @@ gboolean record_matches_pid(struct graph_info *ginfo,
         return FALSE;
 }
 
-void set_cpu_to_time(int cpu, struct graph_info *ginfo, unsigned long long time)
+static void set_cpu_to_time(int cpu, struct graph_info *ginfo, unsigned long long time)
 {
         struct record *record;
 
@@ -92,7 +92,7 @@ void set_cpu_to_time(int cpu, struct graph_info *ginfo, unsigned long long time)
                 tracecmd_set_cpu_to_timestamp(ginfo->handle, cpu, time);
 }
 
-void set_cpus_to_time(struct graph_info *ginfo, unsigned long long time)
+static void set_cpus_to_time(struct graph_info *ginfo, unsigned long long time)
 {
         int cpu;
 
@@ -177,7 +177,7 @@ void restore_offsets(struct graph_info *ginfo, struct offset_cache *offsets)
         free(offsets);
 }
 
-struct record *
+static struct record *
 find_record(struct graph_info *ginfo, gint pid, guint64 time)
 {
         struct record *record = NULL;
@@ -207,6 +207,7 @@ find_record(struct graph_info *ginfo, gint pid, guint64 time)
         return record;
 }
 
+
 int task_plot_display_last_event(struct graph_info *ginfo,
                                  struct graph_plot *plot,
                                  struct trace_seq *s,
@@ -263,7 +264,6 @@ int task_plot_display_last_event(struct graph_info *ginfo,
                                          pid);
                 }
         } else {
-                        
                 /* Must have the record we want */
                 type = pevent_data_type(ginfo->pevent, record);
                 event = pevent_data_event_from_type(ginfo->pevent, type);
diff --git a/trace-plot-task.h b/trace-plot-task.h
index 78ff68f..e050512 100644
--- a/trace-plot-task.h
+++ b/trace-plot-task.h
@@ -41,9 +41,6 @@ struct task_plot_info {
 
 /* Querying records */
 gboolean is_running(struct graph_info *ginfo, struct record *record);
-/* gboolean record_matches_pid(struct graph_info *ginfo, struct record *record, */
-/*                          int match_pid, int *pid, int *sched_pid, */
-/*                          gboolean *is_sched, gboolean *wakeup); */
 
 /* State maintenance */
 void update_last_task_record(struct graph_info *ginfo, struct task_plot_info *task_info,
@@ -51,20 +48,11 @@ void update_last_task_record(struct graph_info *ginfo, struct task_plot_info *ta
 
 /* Searching for records */
 #define MAX_SEARCH 20
-struct record *
-find_record(struct graph_info *ginfo, gint pid, guint64 time);
 struct record *find_previous_record(struct graph_info *ginfo,
                                            struct record *start_record,
                                            int pid, int cpu);
 struct record *get_display_record(struct graph_info *ginfo, int pid,
                                   unsigned long long time);
-gboolean record_matches_pid(struct graph_info *ginfo, struct record *record,
-                            int match_pid, int *pid, int *sched_pid,
-                            gboolean *is_sched, gboolean *wakeup);
-
-/* Seeking in data file */
-void set_cpu_to_time(int cpu, struct graph_info *ginfo, unsigned long long time);
-void set_cpus_to_time(struct graph_info *ginfo, unsigned long long time);
 
 /* Saving / restoring state */
 struct offset_cache {