static GHashTable *threads = NULL;
static GPtrArray *elements = NULL;
static GPtrArray *pads = NULL;
+static GHashTable *latencies = NULL;
+static GHashTable *element_latencies = NULL;
+static GQueue *element_reported_latencies = NULL;
static guint64 num_buffers = 0, num_events = 0, num_messages = 0, num_queries =
0;
static guint num_elements = 0, num_bins = 0, num_pads = 0, num_ghostpads = 0;
+static GstClockTime last_ts = G_GUINT64_CONSTANT (0);
+static guint total_cpuload = 0;
+static gboolean have_cpuload = FALSE;
+
+static gboolean have_latency = FALSE;
+static gboolean have_element_latency = FALSE;
+static gboolean have_element_reported_latency = FALSE;
+
+typedef struct
+{
+ /* the number of latencies counted */
+ guint64 count;
+ /* the total of all latencies */
+ guint64 total;
+ /* the min of all latencies */
+ guint64 min;
+ /* the max of all latencies */
+ guint64 max;
+} GstLatencyStats;
+
+typedef struct
+{
+ /* The element name */
+ gchar *element;
+ /* The timestamp of the reported latency */
+ guint64 ts;
+ /* the min reported latency */
+ guint64 min;
+ /* the max reported latency */
+ guint64 max;
+} GstReportedLatency;
typedef struct
{
/* first and last activity on the pad, expected next_ts */
GstClockTime first_ts, last_ts, next_ts;
/* in which thread does it operate */
- guint thread_id;
+ gpointer thread_id;
/* hierarchy */
guint parent_ix;
} GstPadStats;
guint num_events, num_messages, num_queries;
/* first activity on the element */
GstClockTime first_ts, last_ts;
- /* time spend in this element */
- GstClockTime treal;
/* hierarchy */
guint parent_ix;
} GstElementStats;
typedef struct
{
/* time spend in this thread */
- GstClockTime treal;
- guint max_cpuload;
+ GstClockTime tthread;
+ guint cpuload;
} GstThreadStats;
/* stats helper */
static void
+latencies_foreach_print_stats (gchar * key, GstLatencyStats * ls, gpointer data)
+{
+ printf ("\t%s: mean=%" G_GUINT64_FORMAT " min=%" G_GUINT64_FORMAT " max=%"
+ G_GUINT64_FORMAT "\n", key, ls->total / ls->count, ls->min, ls->max);
+}
+
+static void
+reported_latencies_foreach_print_stats (GstReportedLatency * rl, gpointer data)
+{
+ printf ("\t%s: min=%" G_GUINT64_FORMAT " max=%" G_GUINT64_FORMAT " ts=%"
+ GST_TIME_FORMAT "\n", rl->element, rl->min,
+ rl->max, GST_TIME_ARGS (rl->ts));
+}
+
+static void
+free_latency_stats (gpointer data)
+{
+ g_slice_free (GstLatencyStats, data);
+}
+
+static void
+free_reported_latency (gpointer data)
+{
+ GstReportedLatency *rl = data;
+
+ if (rl->element)
+ g_free (rl->element);
+
+ g_free (data);
+}
+
+static void
free_element_stats (gpointer data)
{
g_slice_free (GstElementStats, data);
static inline GstElementStats *
get_element_stats (guint ix)
{
- return (ix != G_MAXUINT) ? g_ptr_array_index (elements, ix) : NULL;
+ return (ix != G_MAXUINT && ix < elements->len) ?
+ g_ptr_array_index (elements, ix) : NULL;
}
static inline GstPadStats *
get_pad_stats (guint ix)
{
- return (ix != G_MAXUINT) ? g_ptr_array_index (pads, ix) : NULL;
+ return (ix != G_MAXUINT && ix < pads->len) ?
+ g_ptr_array_index (pads, ix) : NULL;
}
static void
g_slice_free (GstPadStats, data);
}
+static inline GstThreadStats *
+get_thread_stats (gpointer id)
+{
+ GstThreadStats *stats = g_hash_table_lookup (threads, id);
+
+ if (G_UNLIKELY (!stats)) {
+ stats = g_slice_new0 (GstThreadStats);
+ stats->tthread = GST_CLOCK_TIME_NONE;
+ g_hash_table_insert (threads, id, stats);
+ }
+ return stats;
+}
+
static void
new_pad_stats (GstStructure * s)
{
gchar *type, *name;
gboolean is_ghost_pad;
GstPadDirection dir;
- guint thread_id;
+ guint64 thread_id;
gst_structure_get (s,
"ix", G_TYPE_UINT, &ix,
"type", G_TYPE_STRING, &type,
"is-ghostpad", G_TYPE_BOOLEAN, &is_ghost_pad,
"pad-direction", GST_TYPE_PAD_DIRECTION, &dir,
- "thread-id", G_TYPE_UINT, &thread_id, NULL);
+ "thread-id", G_TYPE_UINT64, &thread_id, NULL);
stats = g_slice_new0 (GstPadStats);
if (is_ghost_pad)
stats->dir = dir;
stats->min_size = G_MAXUINT;
stats->first_ts = stats->last_ts = stats->next_ts = GST_CLOCK_TIME_NONE;
- stats->thread_id = thread_id;
+ stats->thread_id = (gpointer) (guintptr) thread_id;
stats->parent_ix = parent_ix;
if (pads->len <= ix)
g_ptr_array_set_size (pads, ix + 1);
g_ptr_array_index (pads, ix) = stats;
-
- if (thread_id) {
- GstThreadStats *thread_stats;
- if (!(thread_stats = g_hash_table_lookup (threads,
- GUINT_TO_POINTER (thread_id)))) {
- thread_stats = g_slice_new0 (GstThreadStats);
- g_hash_table_insert (threads, GUINT_TO_POINTER (thread_id), thread_stats);
- }
- }
}
static void
stats->parent_ix = elem_ix;
}
+ if (stats->thread_id) {
+ get_thread_stats (stats->thread_id);
+ }
+
/* size stats */
avg_size = (((gulong) stats->avg_size * (gulong) stats->num_buffers) + size);
stats->num_buffers++;
static void
do_buffer_stats (GstStructure * s)
{
- guint64 ts, buffer_ts, buffer_dur;
+ guint64 ts;
+ guint64 buffer_pts = GST_CLOCK_TIME_NONE, buffer_dur = GST_CLOCK_TIME_NONE;
guint pad_ix, elem_ix, peer_elem_ix;
guint size;
GstBufferFlags buffer_flags;
num_buffers++;
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
"pad-ix", G_TYPE_UINT, &pad_ix,
- "elem-ix", G_TYPE_UINT, &elem_ix,
- "peer-elem-ix", G_TYPE_UINT, &peer_elem_ix,
+ "element-ix", G_TYPE_UINT, &elem_ix,
+ "peer-element-ix", G_TYPE_UINT, &peer_elem_ix,
"buffer-size", G_TYPE_UINT, &size,
- "buffer-ts", G_TYPE_UINT64, &buffer_ts,
- "buffer-duration", G_TYPE_UINT64, &buffer_dur,
"buffer-flags", GST_TYPE_BUFFER_FLAGS, &buffer_flags, NULL);
+ gst_structure_get_uint64 (s, "buffer-pts", &buffer_pts);
+ gst_structure_get_uint64 (s, "buffer-duration", &buffer_dur);
+ last_ts = MAX (last_ts, ts);
if (!(pad_stats = get_pad_stats (pad_ix))) {
GST_WARNING ("no pad stats found for ix=%u", pad_ix);
return;
GST_WARNING ("no element stats found for ix=%u", peer_elem_ix);
return;
}
- do_pad_stats (pad_stats, elem_ix, size, ts, buffer_ts, buffer_dur,
+ do_pad_stats (pad_stats, elem_ix, size, ts, buffer_pts, buffer_dur,
buffer_flags);
if (pad_stats->dir == GST_PAD_SRC) {
/* push */
num_events++;
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
- "pad-ix", G_TYPE_UINT, &pad_ix, "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+ "pad-ix", G_TYPE_UINT, &pad_ix, "element-ix", G_TYPE_UINT, &elem_ix,
+ NULL);
+ last_ts = MAX (last_ts, ts);
if (!(pad_stats = get_pad_stats (pad_ix))) {
GST_WARNING ("no pad stats found for ix=%u", pad_ix);
return;
num_messages++;
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
- "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+ "element-ix", G_TYPE_UINT, &elem_ix, NULL);
+ last_ts = MAX (last_ts, ts);
if (!(elem_stats = get_element_stats (elem_ix))) {
GST_WARNING ("no element stats found for ix=%u", elem_ix);
return;
num_queries++;
gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
- "elem-ix", G_TYPE_UINT, &elem_ix, NULL);
+ "element-ix", G_TYPE_UINT, &elem_ix, NULL);
+ last_ts = MAX (last_ts, ts);
if (!(elem_stats = get_element_stats (elem_ix))) {
GST_WARNING ("no element stats found for ix=%u", elem_ix);
return;
elem_stats->num_queries++;
}
+static void
+do_thread_rusage_stats (GstStructure * s)
+{
+ guint64 ts, tthread, thread_id;
+ guint cpuload;
+ GstThreadStats *thread_stats;
+
+ gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+ "thread-id", G_TYPE_UINT64, &thread_id,
+ "average-cpuload", G_TYPE_UINT, &cpuload, "time", G_TYPE_UINT64, &tthread,
+ NULL);
+ thread_stats = get_thread_stats ((gpointer) (guintptr) thread_id);
+ thread_stats->cpuload = cpuload;
+ thread_stats->tthread = tthread;
+ last_ts = MAX (last_ts, ts);
+}
+
+static void
+do_proc_rusage_stats (GstStructure * s)
+{
+ guint64 ts;
+
+ gst_structure_get (s, "ts", G_TYPE_UINT64, &ts,
+ "average-cpuload", G_TYPE_UINT, &total_cpuload, NULL);
+ last_ts = MAX (last_ts, ts);
+ have_cpuload = TRUE;
+}
+
+static void
+update_latency_table (GHashTable * table, const gchar * key, guint64 time)
+{
+ /* Find the values in the hash table */
+ GstLatencyStats *ls = g_hash_table_lookup (table, key);
+ if (!ls) {
+ /* Insert the new key if the value does not exist */
+ ls = g_new0 (GstLatencyStats, 1);
+ ls->count = 1;
+ ls->total = time;
+ ls->min = time;
+ ls->max = time;
+ g_hash_table_insert (table, g_strdup (key), ls);
+ } else {
+ /* Otherwise update the existing value */
+ ls->count++;
+ ls->total += time;
+ if (ls->min > time)
+ ls->min = time;
+ if (ls->max < time)
+ ls->max = time;
+ }
+}
+
+static void
+do_latency_stats (GstStructure * s)
+{
+ gchar *key = NULL;
+ const gchar *src = NULL, *sink = NULL;
+ guint64 ts = 0, time = 0;
+
+ /* Get the values from the structure */
+ src = gst_structure_get_string (s, "src");
+ sink = gst_structure_get_string (s, "sink");
+ gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
+ gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
+
+ /* Update last_ts */
+ last_ts = MAX (last_ts, ts);
+
+ /* Get the key */
+ key = g_strjoin ("|", src, sink, NULL);
+
+ /* Update the latency in the table */
+ update_latency_table (latencies, key, time);
+
+ /* Clean up */
+ g_free (key);
+
+ have_latency = TRUE;
+}
+
+static void
+do_element_latency_stats (GstStructure * s)
+{
+ const gchar *src = NULL;
+ guint64 ts = 0, time = 0;
+
+ /* Get the values from the structure */
+ src = gst_structure_get_string (s, "src");
+ gst_structure_get (s, "time", G_TYPE_UINT64, &time, NULL);
+ gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
+
+ /* Update last_ts */
+ last_ts = MAX (last_ts, ts);
+
+ /* Update the latency in the table */
+ update_latency_table (element_latencies, src, time);
+
+ have_element_latency = TRUE;
+}
+
+static void
+do_element_reported_latency (GstStructure * s)
+{
+ const gchar *element = NULL;
+ guint64 ts = 0, min = 0, max = 0;
+ GstReportedLatency *rl = NULL;
+
+ /* Get the values from the structure */
+ element = gst_structure_get_string (s, "element");
+ gst_structure_get (s, "min", G_TYPE_UINT64, &min, NULL);
+ gst_structure_get (s, "max", G_TYPE_UINT64, &max, NULL);
+ gst_structure_get (s, "ts", G_TYPE_UINT64, &ts, NULL);
+
+ /* Update last_ts */
+ last_ts = MAX (last_ts, ts);
+
+ /* Insert/Update the key in the table */
+ rl = g_new0 (GstReportedLatency, 1);
+ rl->element = g_strdup (element);
+ rl->ts = ts;
+ rl->min = min;
+ rl->max = max;
+ g_queue_push_tail (element_reported_latencies, rl);
+
+ have_element_reported_latency = TRUE;
+}
+
/* reporting */
static gint
{
const GstPadStats *stats = (const GstPadStats *) value;
- if ((stats->thread_id == GPOINTER_TO_UINT (user_data)) &&
- (stats->num_buffers)) {
+ if ((stats->thread_id == user_data) && (stats->num_buffers)) {
return 0;
}
return 1;
{
GstPadStats *stats = (GstPadStats *) value;
- if (stats->thread_id == GPOINTER_TO_UINT (user_data)) {
+ if (stats->thread_id == user_data) {
/* there seem to be some temporary pads */
if (stats->num_buffers) {
GstClockTimeDiff running =
{
GSList *list = user_data;
GSList *node = g_slist_find_custom (list, key, find_pad_stats_for_thread);
+ GstThreadStats *stats = (GstThreadStats *) value;
/* skip stats if there are no pads for that thread (e.g. a pipeline) */
if (!node)
return;
-#if 0
- GstThreadStats *stats = (GstThreadStats *) value;
- guint cpuload = 0;
- guint time_percent;
-
- time_percent =
- (guint) gst_util_uint64_scale (stats->treal, G_GINT64_CONSTANT (100),
- last_ts);
-
- if (tusersys) {
- guint64 total;
- /* cpuload for the process, scaled by the timeslice of this thread */
- //cpuload = (guint) gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT(100) * stats->treal, last_ts * last_ts);
-
- total = gst_util_uint64_scale (tusersys, G_GINT64_CONSTANT (100), last_ts);
- cpuload = gst_util_uint64_scale (total, stats->treal, last_ts);
- }
-#endif
-
printf ("Thread %p Statistics:\n", key);
-#if 0
- printf (" Time: %" GST_TIME_FORMAT ", %u %%\n", GST_TIME_ARGS (stats->treal),
- (guint) time_percent);
- printf (" Avg/Max CPU load: %u %%, %u %%\n", cpuload, stats->max_cpuload);
-#endif
+ if (GST_CLOCK_TIME_IS_VALID (stats->tthread)) {
+ printf (" Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (stats->tthread));
+ printf (" Avg CPU load: %4.1f %%\n", (gfloat) stats->cpuload / 10.0);
+ }
puts (" Pad Statistics:");
g_slist_foreach (node, print_pad_stats, key);
/* skip temporary elements */
if (stats->first_ts != GST_CLOCK_TIME_NONE) {
- //GstClockTimeDiff running = GST_CLOCK_DIFF (stats->first_ts, stats->last_ts);
gchar fullname[45 + 1];
g_snprintf (fullname, 45, "%s:%s", stats->type_name, stats->name);
printf ("/%12" G_GUINT64_FORMAT, stats->sent_bytes);
else
printf ("/%12s", "-");
- printf (" first activity %" GST_TIME_FORMAT ", " " ev/msg/qry sent %5u/%5u/%5u" /*", "
- " cpu usage %u %%" */
- "\n", GST_TIME_ARGS (stats->first_ts), stats->num_events, stats->num_messages, stats->num_queries /*,
- (guint)(100*stats->treal/last_ts) */ );
+ printf (" first activity %" GST_TIME_FORMAT ", "
+ " ev/msg/qry sent %5u/%5u/%5u\n", GST_TIME_ARGS (stats->first_ts),
+ stats->num_events, stats->num_messages, stats->num_queries);
}
}
/* 5: category */
"([a-zA-Z_-]+) +"
/* 6: file:line:func: */
- "([^:]+:[0-9]+:[^:]+:)"
+ "([^:]*:[0-9]+:[^:]*:) +"
/* 7: (obj)? log-text */
"(.*)$", 0, 0, NULL);
if (!raw_log) {
/* 1: ts */
"^([0-9:.]+) +"
/* 2: pid */
- "\\\e\\\[[0-9;]+m *([0-9]+)\\\e\\\[00m +"
+ "\\\x1b\\[[0-9;]+m *([0-9]+)\\\x1b\\[00m +"
/* 3: thread */
"(0x[0-9a-fA-F]+) +"
/* 4: level */
- "(?:\\\e\\\[[0-9;]+m)?([A-Z]+) +\\\e\\\[00m +"
+ "(?:\\\x1b\\[[0-9;]+m)?([A-Z]+) +\\\x1b\\[00m +"
/* 5: category */
- "\\\e\\\[[0-9;]+m +([a-zA-Z_-]+) +"
+ "\\\x1b\\[[0-9;]+m +([a-zA-Z_-]+) +"
/* 6: file:line:func: */
- "([^:]+:[0-9]+:[^:]+:)(?:\\\e\\\[00m)?"
+ "([^:]*:[0-9]+:[^:]*:)(?:\\\x1b\\[00m)? +"
/* 7: (obj)? log-text */
"(.*)$", 0, 0, NULL);
if (!raw_log) {
elements = g_ptr_array_new_with_free_func (free_element_stats);
pads = g_ptr_array_new_with_free_func (free_pad_stats);
threads = g_hash_table_new_full (NULL, NULL, NULL, free_thread_stats);
+ latencies = g_hash_table_new_full (g_str_hash, g_str_equal, g_free,
+ free_latency_stats);
+ element_latencies = g_hash_table_new_full (g_str_hash, g_str_equal, g_free,
+ free_latency_stats);
+ element_reported_latencies = g_queue_new ();
return TRUE;
}
if (threads)
g_hash_table_destroy (threads);
+ if (latencies) {
+ g_hash_table_remove_all (latencies);
+ g_hash_table_destroy (latencies);
+ latencies = NULL;
+ }
+ if (element_latencies) {
+ g_hash_table_remove_all (element_latencies);
+ g_hash_table_destroy (element_latencies);
+ element_latencies = NULL;
+ }
+ if (element_reported_latencies) {
+ g_queue_free_full (element_reported_latencies, free_reported_latency);
+ element_reported_latencies = NULL;
+ }
+
if (raw_log)
g_regex_unref (raw_log);
if (ansi_log)
printf ("Number of Events sent: %" G_GUINT64_FORMAT "\n", num_events);
printf ("Number of Message sent: %" G_GUINT64_FORMAT "\n", num_messages);
printf ("Number of Queries sent: %" G_GUINT64_FORMAT "\n", num_queries);
+ printf ("Time: %" GST_TIME_FORMAT "\n", GST_TIME_ARGS (last_ts));
+ if (have_cpuload) {
+ printf ("Avg CPU load: %4.1f %%\n", (gfloat) total_cpuload / 10.0);
+ }
puts ("");
/* thread stats */
puts ("");
g_slist_free (list);
}
+
+ /* latency stats */
+ if (have_latency) {
+ puts ("Latency Statistics:");
+ g_hash_table_foreach (latencies, (GHFunc) latencies_foreach_print_stats,
+ NULL);
+ puts ("");
+ }
+
+ /* element latency stats */
+ if (have_element_latency) {
+ puts ("Element Latency Statistics:");
+ g_hash_table_foreach (element_latencies,
+ (GHFunc) latencies_foreach_print_stats, NULL);
+ puts ("");
+ }
+
+ /* element reported latency stats */
+ if (have_element_reported_latency) {
+ puts ("Element Reported Latency:");
+ g_queue_foreach (element_reported_latencies,
+ (GFunc) reported_latencies_foreach_print_stats, NULL);
+ puts ("");
+ }
}
static void
if ((s = gst_structure_from_string (data, NULL))) {
const gchar *name = gst_structure_get_name (s);
- // TODO(ensonic): add a function for each name-id quark
- // these function will do the actual stats tracking
if (!strcmp (name, "new-pad")) {
new_pad_stats (s);
} else if (!strcmp (name, "new-element")) {
do_message_stats (s);
} else if (!strcmp (name, "query")) {
do_query_stats (s);
+ } else if (!strcmp (name, "thread-rusage")) {
+ do_thread_rusage_stats (s);
+ } else if (!strcmp (name, "proc-rusage")) {
+ do_proc_rusage_stats (s);
+ } else if (!strcmp (name, "latency")) {
+ do_latency_stats (s);
+ } else if (!strcmp (name, "element-latency")) {
+ do_element_latency_stats (s);
+ } else if (!strcmp (name, "element-reported-latency")) {
+ do_element_reported_latency (s);
} else {
- GST_WARNING ("unknown log entry: '%s'", data);
+ // TODO(ensonic): parse the xxx.class log lines
+ if (!g_str_has_suffix (data, ".class")) {
+ GST_WARNING ("unknown log entry: '%s'", data);
+ }
}
gst_structure_free (s);
} else {
}
}
}
- fclose (log);
- // TODO(ensonic): print stats
} else {
GST_WARNING ("empty log");
}
+ fclose (log);
}
}