From 9dba2a52db2adb42e7c1a292625bd0114ce81969 Mon Sep 17 00:00:00 2001 From: wm4 Date: Thu, 17 Apr 2014 21:47:00 +0200 Subject: player: add a --dump-stats option This collects statistics and other things. The option dumps raw data into a file. A script to visualize this data is included too. Litter some of the player code with calls that generate these statistics. In general, this will be helpful to debug timing dependent issues, such as A/V sync problems. Normally, one could argue that this is the task of a real profiler, but then we'd have a hard time to include extra information like audio/video PTS differences. We could also just hardcode all statistics collection and processing in the player code, but then we'd end up with something like mplayer's status line, which was cluttered and required a centralized approach (i.e. getting the data to the status line; so it was all in mplayer.c). Some players can visualize such statistics on OSD, but that sounds even more complicated. So the approach added with this commit sounds sensible. The stats-conv.py script is rather primitive at the moment and its output is semi-ugly. It uses matplotlib, so it could probably be extended to do a lot, so it's not a dead-end. --- common/msg.c | 42 ++++++++++++++++++++++++++++++++++++++++-- common/msg.h | 6 ++++++ common/msg_control.h | 2 ++ 3 files changed, 48 insertions(+), 2 deletions(-) (limited to 'common') diff --git a/common/msg.c b/common/msg.c index 9ee0651a1a..2caa048e40 100644 --- a/common/msg.c +++ b/common/msg.c @@ -23,6 +23,7 @@ #include #include #include +#include #include "talloc.h" @@ -59,6 +60,7 @@ struct mp_log_root { bool force_stderr; struct mp_log_buffer **buffers; int num_buffers; + FILE *stats_file; // --- semi-atomic access bool mute; // --- must be accessed atomically @@ -119,6 +121,8 @@ static void update_loglevel(struct mp_log *log) } for (int n = 0; n < log->root->num_buffers; n++) log->level = MPMAX(log->level, log->root->buffers[n]->level); + if (log->root->stats_file) + log->level = MPMAX(log->level, MSGL_STATS); log->reload_counter = log->root->reload_counter; pthread_mutex_unlock(&mp_msg_lock); } @@ -200,7 +204,7 @@ bool mp_msg_has_status_line(struct mpv_global *global) static void set_msg_color(FILE* stream, int lev) { - static const int v_colors[] = {9, 1, 3, -1, -1, 2, 8, 8, -1}; + static const int v_colors[] = {9, 1, 3, -1, -1, 2, 8, 8, 8, -1}; terminal_set_foreground_color(stream, v_colors[lev]); } @@ -256,6 +260,8 @@ static void print_msg_on_terminal(struct mp_log *log, int lev, char *text) flush_status_line(root); size_t len = strlen(text); root->header = len && text[len - 1] == '\n'; + if (lev == MSGL_STATS) + terminate = "\n"; } if (root->color) @@ -320,6 +326,15 @@ static void write_msg_to_buffers(struct mp_log *log, int lev, char *text) } } +static void dump_stats(struct mp_log *log, int lev, char *text) +{ + struct mp_log_root *root = log->root; + if (lev == MSGL_STATS && root->stats_file) { + fprintf(root->stats_file, "%"PRId64" %s #%s\n", mp_time_us(), text, + log->verbose_prefix); + } +} + void mp_msg_va(struct mp_log *log, int lev, const char *format, va_list va) { if (!mp_msg_test(log, lev)) @@ -336,6 +351,7 @@ void mp_msg_va(struct mp_log *log, int lev, const char *format, va_list va) print_msg_on_terminal(log, lev, text); write_msg_to_buffers(log, lev, text); + dump_stats(log, lev, text); pthread_mutex_unlock(&mp_msg_lock); } @@ -438,7 +454,10 @@ void mp_msg_force_stderr(struct mpv_global *global, bool force_stderr) void mp_msg_uninit(struct mpv_global *global) { - talloc_free(global->log->root); + struct mp_log_root *root = global->log->root; + if (root->stats_file) + fclose(root->stats_file); + talloc_free(root); global->log = NULL; } @@ -514,6 +533,24 @@ struct mp_log_buffer_entry *mp_msg_log_buffer_read(struct mp_log_buffer *buffer) return ptr; } +int mp_msg_open_stats_file(struct mpv_global *global, const char *path) +{ + struct mp_log_root *root = global->log->root; + int r; + + pthread_mutex_lock(&mp_msg_lock); + + if (root->stats_file) + fclose(root->stats_file); + root->stats_file = fopen(path, "wb"); + r = root->stats_file ? 0 : -1; + + pthread_mutex_unlock(&mp_msg_lock); + + mp_msg_update_msglevels(global); + return r; +} + // Thread-safety: fully thread-safe, but keep in mind that the lifetime of // log must be guaranteed during the call. // Never call this from signal handlers. @@ -534,6 +571,7 @@ char *mp_log_levels[MSGL_MAX + 1] = { [MSGL_V] = "v", [MSGL_DEBUG] = "debug", [MSGL_TRACE] = "trace", + [MSGL_STATS] = "stats", }; int mp_msg_split_msglevel(struct bstr *s, struct bstr *out_mod, int *out_level) diff --git a/common/msg.h b/common/msg.h index d56ce13976..61997e946d 100644 --- a/common/msg.h +++ b/common/msg.h @@ -41,6 +41,7 @@ enum { MSGL_V, // -v MSGL_DEBUG, // -v -v MSGL_TRACE, // -v -v -v + MSGL_STATS, // dumping fine grained stats (--dump-stats) MSGL_SMODE, // old slave mode (-identify) MSGL_MAX = MSGL_SMODE, @@ -78,4 +79,9 @@ bool mp_msg_test(struct mp_log *log, int lev); #define MP_TRACE(obj, ...) MP_MSG(obj, MSGL_TRACE, __VA_ARGS__) #define MP_SMODE(obj, ...) MP_MSG(obj, MSGL_SMODE, __VA_ARGS__) +// This is a bit special. See TOOLS/stats-conv.py what rules text passed +// to these functions should follow. Also see --dump-stats. +#define mp_stats(obj, ...) mp_msg(obj, MSGL_STATS, __VA_ARGS__) +#define MP_STATS(obj, ...) MP_MSG(obj, MSGL_STATS, __VA_ARGS__) + #endif /* MPLAYER_MP_MSG_H */ diff --git a/common/msg_control.h b/common/msg_control.h index ecce7ca0eb..49eeee025c 100644 --- a/common/msg_control.h +++ b/common/msg_control.h @@ -24,6 +24,8 @@ struct mp_log_buffer *mp_msg_log_buffer_new(struct mpv_global *global, void mp_msg_log_buffer_destroy(struct mp_log_buffer *buffer); struct mp_log_buffer_entry *mp_msg_log_buffer_read(struct mp_log_buffer *buffer); +int mp_msg_open_stats_file(struct mpv_global *global, const char *path); + struct bstr; int mp_msg_split_msglevel(struct bstr *s, struct bstr *out_mod, int *out_level); -- cgit v1.2.3