From b305fe1222b244f020e22c31b204375cf02b823e Mon Sep 17 00:00:00 2001 From: Jonathan Date: Tue, 6 Mar 2012 23:18:16 -0500 Subject: 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. --- Documentation/structure.txt | 26 ++++-- parse-events.h | 1 + rt-graph.c | 1 - rt-graph.h | 4 +- rt-plot-task.c | 215 ++++++++++++++++++++++++++++++++++++++++++-- trace-input.c | 2 + trace-plot-task.c | 18 ++-- trace-plot-task.h | 12 --- 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 { -- cgit v1.2.2