static void log_new_element_stats (GstElementStats * stats, GstElement * element, GstClockTime elapsed) { gst_tracer_record_log (tr_new_element, (guint64) (guintptr) g_thread_self (), elapsed, stats->index, stats->parent_ix, GST_OBJECT_NAME (element), G_OBJECT_TYPE_NAME (element), GST_IS_BIN (element)); }
static void log_new_pad_stats (GstPadStats * stats, GstPad * pad) { gst_tracer_record_log (tr_new_pad, (guint64) (guintptr) g_thread_self (), stats->index, stats->parent_ix, GST_OBJECT_NAME (pad), G_OBJECT_TYPE_NAME (pad), GST_IS_GHOST_PAD (pad), GST_PAD_DIRECTION (pad)); }
static void do_element_query_pre (GstStatsTracer * self, guint64 ts, GstElement * elem, GstQuery * qry) { GstElementStats *stats = get_element_stats (self, elem); stats->last_ts = ts; gst_tracer_record_log (tr_element_query, (guint64) (guintptr) g_thread_self (), ts, stats->index, GST_QUERY_TYPE_NAME (qry)); }
static void do_push_event_pre (GstStatsTracer * self, guint64 ts, GstPad * pad, GstEvent * ev) { GstElement *elem = get_real_pad_parent (pad); GstElementStats *elem_stats = get_element_stats (self, elem); GstPadStats *pad_stats = get_pad_stats (self, pad); elem_stats->last_ts = ts; gst_tracer_record_log (tr_event, (guint64) (guintptr) g_thread_self (), ts, pad_stats->index, elem_stats->index, GST_EVENT_TYPE_NAME (ev)); }
static void do_post_message_pre (GstStatsTracer * self, guint64 ts, GstElement * elem, GstMessage * msg) { GstElementStats *stats = get_element_stats (self, elem); const GstStructure *msg_s = gst_message_get_structure (msg); GstStructure *s = msg_s ? (GstStructure *) msg_s : gst_structure_new_empty ("dummy"); stats->last_ts = ts; /* FIXME: work out whether using NULL instead of a dummy struct would work */ gst_tracer_record_log (tr_message, (guint64) (guintptr) g_thread_self (), ts, stats->index, GST_MESSAGE_TYPE_NAME (msg), s); if (s != msg_s) gst_structure_free (s); }
static void do_query_stats (GstStatsTracer * self, GstPad * this_pad, GstPadStats * this_pad_stats, GstPad * that_pad, GstPadStats * that_pad_stats, GstQuery * qry, GstClockTime elapsed, gboolean have_res, gboolean res) { GstElement *this_elem = get_real_pad_parent (this_pad); GstElementStats *this_elem_stats = get_element_stats (self, this_elem); GstElement *that_elem = get_real_pad_parent (that_pad); GstElementStats *that_elem_stats = get_element_stats (self, that_elem); gst_tracer_record_log (tr_query, (guint64) (guintptr) g_thread_self (), elapsed, this_pad_stats->index, this_elem_stats->index, that_pad_stats->index, that_elem_stats->index, GST_QUERY_TYPE_NAME (qry), gst_query_get_structure (qry), have_res, res); }
static void log_latency (const GstStructure * data, GstPad * sink_pad, guint64 sink_ts) { GstPad *src_pad; guint64 src_ts; gchar *src, *sink; gst_structure_id_get (data, latency_probe_pad, GST_TYPE_PAD, &src_pad, latency_probe_ts, G_TYPE_UINT64, &src_ts, NULL); src = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (src_pad)); sink = g_strdup_printf ("%s_%s", GST_DEBUG_PAD_NAME (sink_pad)); gst_tracer_record_log (tr_latency, src, sink, GST_CLOCK_DIFF (src_ts, sink_ts)); g_free (src); g_free (sink); }
static void do_buffer_stats (GstStatsTracer * self, GstPad * this_pad, GstPadStats * this_pad_stats, GstPad * that_pad, GstPadStats * that_pad_stats, GstBuffer * buf, GstClockTime elapsed) { GstElement *this_elem = get_real_pad_parent (this_pad); GstElementStats *this_elem_stats = get_element_stats (self, this_elem); GstElement *that_elem = get_real_pad_parent (that_pad); GstElementStats *that_elem_stats = get_element_stats (self, that_elem); GstClockTime pts = GST_BUFFER_PTS (buf); GstClockTime dts = GST_BUFFER_DTS (buf); GstClockTime dur = GST_BUFFER_DURATION (buf); gst_tracer_record_log (tr_buffer, (guint64) (guintptr) g_thread_self (), elapsed, this_pad_stats->index, this_elem_stats->index, that_pad_stats->index, that_elem_stats->index, gst_buffer_get_size (buf), GST_CLOCK_TIME_IS_VALID (pts), pts, GST_CLOCK_TIME_IS_VALID (dts), dts, GST_CLOCK_TIME_IS_VALID (dur), dur, GST_BUFFER_FLAGS (buf)); }
static void do_stats (GstTracer * obj, guint64 ts) { GstRUsageTracer *self = GST_RUSAGE_TRACER_CAST (obj); GstThreadStats *stats; gpointer thread_id = g_thread_self (); guint avg_cpuload, cur_cpuload; struct rusage ru; GstClockTime tproc = G_GUINT64_CONSTANT (0); GstClockTime tthread = G_GUINT64_CONSTANT (0); GstClockTime dts, dtproc; #ifdef HAVE_CLOCK_GETTIME { struct timespec now; if (!clock_gettime (CLOCK_PROCESS_CPUTIME_ID, &now)) { tproc = GST_TIMESPEC_TO_TIME (now); } else { GST_WARNING_OBJECT (obj, "clock_gettime (CLOCK_PROCESS_CPUTIME_ID,...) failed: %s", g_strerror (errno)); getrusage (RUSAGE_SELF, &ru); tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime); } /* cpu time per thread */ if (!clock_gettime (CLOCK_THREAD_CPUTIME_ID, &now)) { tthread = GST_TIMESPEC_TO_TIME (now); } else { GST_WARNING_OBJECT (obj, "clock_gettime (CLOCK_THREAD_CPUTIME_ID,...) failed: %s", g_strerror (errno)); #ifdef RUSAGE_THREAD getrusage (RUSAGE_THREAD, &ru); tthread = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime); #endif } } #else getrusage (RUSAGE_SELF, &ru); tproc = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime); #ifdef RUSAGE_THREAD getrusage (RUSAGE_THREAD, &ru); tthread = GST_TIMEVAL_TO_TIME (ru.ru_utime) + GST_TIMEVAL_TO_TIME (ru.ru_stime); #endif #endif /* get stats record for current thread */ if (!(stats = g_hash_table_lookup (self->threads, thread_id))) { stats = g_slice_new0 (GstThreadStats); stats->tvs_thread = make_trace_values (GST_SECOND); g_hash_table_insert (self->threads, thread_id, stats); } stats->tthread = tthread; /* Calibrate ts for the process and main thread. For tthread[main] and tproc * the time is larger than ts, as our base-ts is taken after the process has * started. */ if (G_UNLIKELY (thread_id == self->main_thread_id)) { self->main_thread_id = NULL; /* when the registry gets updated, the tproc is less than the debug time ? */ /* TODO(ensonic): we still see cases where tproc overtakes ts, especially * when with sync=false, can this be due to multiple cores in use? */ if (tproc > ts) { self->tproc_base = tproc - ts; GST_DEBUG ("rusage: calibrating by %" G_GUINT64_FORMAT ", thread: %" G_GUINT64_FORMAT ", proc: %" G_GUINT64_FORMAT, self->tproc_base, stats->tthread, tproc); stats->tthread -= self->tproc_base; } } /* we always need to correct proc time */ tproc -= self->tproc_base; /* FIXME: how can we take cpu-frequency scaling into account? * - looking at /sys/devices/system/cpu/cpu0/cpufreq/ * scale_factor=scaling_max_freq/scaling_cur_freq * - as a workaround we can switch it via /sys/devices/system/cpu/cpu0/cpufreq/scaling_governor * cpufreq-selector -g performance * cpufreq-selector -g ondemand */ /* *INDENT-OFF* */ avg_cpuload = (guint) gst_util_uint64_scale (stats->tthread, G_GINT64_CONSTANT (1000), ts); update_trace_value (stats->tvs_thread, ts, stats->tthread, &dts, &dtproc); cur_cpuload = (guint) gst_util_uint64_scale (dtproc, G_GINT64_CONSTANT (1000), dts); gst_tracer_record_log (tr_thread, (guint64) (guintptr) thread_id, ts, MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), stats->tthread); avg_cpuload = (guint) gst_util_uint64_scale (tproc / num_cpus, G_GINT64_CONSTANT (1000), ts); G_LOCK (_proc); update_trace_value (self->tvs_proc, ts, tproc, &dts, &dtproc); G_UNLOCK (_proc); cur_cpuload = (guint) gst_util_uint64_scale (dtproc / num_cpus, G_GINT64_CONSTANT (1000), dts); gst_tracer_record_log (tr_proc, (guint64) getpid (), ts, MIN (avg_cpuload, 1000), MIN (cur_cpuload, 1000), tproc); /* *INDENT-ON* */ }