diff options
-rw-r--r-- | DOCS/man/en/options.rst | 8 | ||||
-rwxr-xr-x | TOOLS/stats-conv.py | 88 | ||||
-rw-r--r-- | audio/decode/dec_audio.c | 11 | ||||
-rw-r--r-- | common/msg.c | 42 | ||||
-rw-r--r-- | common/msg.h | 6 | ||||
-rw-r--r-- | common/msg_control.h | 2 | ||||
-rw-r--r-- | options/options.c | 1 | ||||
-rw-r--r-- | options/options.h | 1 | ||||
-rw-r--r-- | player/main.c | 8 | ||||
-rw-r--r-- | player/playloop.c | 19 | ||||
-rw-r--r-- | video/decode/dec_video.c | 4 |
11 files changed, 181 insertions, 9 deletions
diff --git a/DOCS/man/en/options.rst b/DOCS/man/en/options.rst index 9e139c0578..d46ba0e959 100644 --- a/DOCS/man/en/options.rst +++ b/DOCS/man/en/options.rst @@ -759,6 +759,14 @@ OPTIONS Time in milliseconds to recognize two consecutive button presses as a double-click (default: 300). +``--dump-stats=<filename>`` + Write certain statistics to the given file. The file is truncated on + opening. The file will contain raw samples, each with a timestamp. To + make this file into a readable, the script ``TOOLS/stats-conv.py`` can be + used (which currently displays it as a graph). + + This option is useful for debugging only. + ``--dvbin=<options>`` Pass the following parameters to the DVB input module, in order to override the default ones: diff --git a/TOOLS/stats-conv.py b/TOOLS/stats-conv.py new file mode 100755 index 0000000000..941cb1539e --- /dev/null +++ b/TOOLS/stats-conv.py @@ -0,0 +1,88 @@ +#!/usr/bin/env python3 +import matplotlib.pyplot as plot +import sys + +filename = sys.argv[1] + +""" +This script is meant to display stats written by mpv --dump-stats=filename. +In general, each line in that file is an event of the form: + + <timestamp in microseconds> <text> '#' <comment> + +e.g.: + + 10474959 start flip #cplayer + +<text> is what MP_STATS(log, "...") writes. The rest is added by msg.c. + +Currently, the following event types are supported: + + 'start' <name> start of the named event + 'end' <name> end of the named event + 'value' <float> <name> a normal value (as opposed to event) + <event> singular event + +""" + +class G: + events = {} + sevents = [] # events, deterministically sorted + start = None + +class Event: + pass + +def get_event(event): + if event not in G.events: + e = Event() + G.events[event] = e + e.name = event + e.vals = [] + e.type = "unknown" + G.sevents = list(G.events.values()) + G.sevents.sort(key=lambda x: x.name) + return G.events[event] + +for line in [line.split("#")[0].strip() for line in open(filename, "r")]: + ts, event = line.split(" ", 1) + ts = int(ts) / 1000 # milliseconds + if G.start is None: + G.start = ts + ts = ts - G.start + if event.startswith("start "): + e = get_event(event[6:]) + e.type = "event" + e.vals.append((ts, 0)) + e.vals.append((ts, 1)) + elif event.startswith("end "): + e = get_event(event[4:]) + e.type = "event" + e.vals.append((ts, 1)) + e.vals.append((ts, 0)) + elif event.startswith("value "): + _, val, name = event.split(" ", 2) + val = float(val) + e = get_event(name) + e.type = "value" + e.vals.append((ts, val)) + else: + e = get_event(event) + e.type = "event-signal" + e.vals.append((ts, 1)) + +plot.hold(True) +mainpl = plot.subplot(2, 1, 1) +legend = [] +for e in G.sevents: + if e.type == "value": + plot.subplot(2, 1, 2, sharex=mainpl) + else: + plot.subplot(2, 1, 1) + pl, = plot.plot([x for x,y in e.vals], [y for x,y in e.vals], label=e.name) + if e.type == "event-signal": + plot.setp(pl, marker = "o", linestyle = "None") + legend.append(pl) +plot.subplot(2, 1, 1) +plot.legend(legend, [pl.get_label() for pl in legend]) +plot.show() diff --git a/audio/decode/dec_audio.c b/audio/decode/dec_audio.c index b44216ec00..46009c6fdd 100644 --- a/audio/decode/dec_audio.c +++ b/audio/decode/dec_audio.c @@ -317,7 +317,9 @@ int audio_decode(struct dec_audio *d_audio, struct mp_audio_buffer *outbuf, double filter_multiplier = af_calc_filter_multiplier(d_audio->afilter); int prev_buffered = -1; - while (minsamples >= 0) { + int res = 0; + MP_STATS(d_audio, "start audio"); + while (res >= 0 && minsamples >= 0) { int buffered = mp_audio_buffer_samples(outbuf); if (minsamples < buffered || buffered == prev_buffered) break; @@ -343,11 +345,10 @@ int audio_decode(struct dec_audio *d_audio, struct mp_audio_buffer *outbuf, * of buffering in filters */ huge_filter_buffer = 1; - int res = filter_n_bytes(d_audio, outbuf, decsamples); - if (res < 0) - return res; + res = filter_n_bytes(d_audio, outbuf, decsamples); } - return 0; + MP_STATS(d_audio, "end audio"); + return res; } void audio_reset_decoding(struct dec_audio *d_audio) 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 <unistd.h> #include <assert.h> #include <pthread.h> +#include <stdint.h> #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); diff --git a/options/options.c b/options/options.c index 82b81b049d..eabdeb0520 100644 --- a/options/options.c +++ b/options/options.c @@ -217,6 +217,7 @@ const m_option_t mp_opts[] = { OPT_FLAG("terminal", use_terminal, CONF_GLOBAL | CONF_PRE_PARSE), OPT_GENERAL(char*, "msglevel", msglevels, CONF_GLOBAL|CONF_PRE_PARSE, .type = &m_option_type_msglevels), + OPT_STRING("dump-stats", dump_stats, CONF_GLOBAL | CONF_PRE_PARSE), OPT_FLAG("msgcolor", msg_color, CONF_GLOBAL | CONF_PRE_PARSE), OPT_FLAG("msgmodule", msg_module, CONF_GLOBAL), OPT_FLAG("msgtime", msg_time, CONF_GLOBAL), diff --git a/options/options.h b/options/options.h index 3572789c5a..9bd60c2630 100644 --- a/options/options.h +++ b/options/options.h @@ -46,6 +46,7 @@ typedef struct mp_vo_opts { typedef struct MPOpts { int use_terminal; char *msglevels; + char *dump_stats; int verbose; int msg_identify; int msg_color; diff --git a/player/main.c b/player/main.c index 3a6084658c..dc685b84f7 100644 --- a/player/main.c +++ b/player/main.c @@ -366,6 +366,12 @@ int mp_initialize(struct MPContext *mpctx) assert(!mpctx->initialized); + if (opts->dump_stats && opts->dump_stats[0]) { + if (mp_msg_open_stats_file(mpctx->global, opts->dump_stats) < 0) + MP_ERR(mpctx, "Failed to open stats file '%s'\n", opts->dump_stats); + } + MP_STATS(mpctx, "start init"); + if (mpctx->opts->use_terminal && !terminal_initialized) { terminal_initialized = true; terminal_init(); @@ -452,6 +458,8 @@ int mp_initialize(struct MPContext *mpctx) if (!mpctx->playlist->current) mpctx->playlist->current = mpctx->playlist->first; + MP_STATS(mpctx, "end init"); + return 0; } diff --git a/player/playloop.c b/player/playloop.c index 84da8d231a..2495579c39 100644 --- a/player/playloop.c +++ b/player/playloop.c @@ -1030,6 +1030,7 @@ void run_playloop(struct MPContext *mpctx) } mpctx->time_frame -= get_relative_time(mpctx); + double audio_pts = playing_audio_pts(mpctx); if (full_audio_buffers && !mpctx->restart_playback) { buffered_audio = ao_get_delay(mpctx->ao); MP_TRACE(mpctx, "audio delay=%f\n", buffered_audio); @@ -1076,14 +1077,21 @@ void run_playloop(struct MPContext *mpctx) //=================== FLIP PAGE (VIDEO BLT): ====================== + MP_STATS(mpctx, "vo draw frame"); + vo_new_frame_imminent(vo); mpctx->video_pts = mpctx->video_next_pts; mpctx->last_vo_pts = mpctx->video_pts; mpctx->playback_pts = mpctx->video_pts; + update_subtitles(mpctx); update_osd_msg(mpctx); + + MP_STATS(mpctx, "draw OSD"); draw_osd(mpctx); + MP_STATS(mpctx, "vo sleep"); + mpctx->time_frame -= get_relative_time(mpctx); mpctx->time_frame -= vo->flip_queue_offset; if (mpctx->time_frame > 0.001) @@ -1120,7 +1128,13 @@ void run_playloop(struct MPContext *mpctx) } if (mpctx->restart_playback) duration = -1; + + MP_STATS(mpctx, "start flip"); vo_flip_page(vo, pts_us | 1, duration); + MP_STATS(mpctx, "end flip"); + + if (audio_pts != MP_NOPTS_VALUE) + MP_STATS(mpctx, "value %f ptsdiff", mpctx->video_pts - audio_pts); mpctx->last_vo_flip_duration = (mp_time_us() - t2) * 0.000001; if (vo->driver->flip_page_timed) { @@ -1256,8 +1270,11 @@ void run_playloop(struct MPContext *mpctx) if (handle_osd_redraw(mpctx)) sleeptime = 0; } - if (sleeptime > 0) + if (sleeptime > 0) { + MP_STATS(mpctx, "start sleep"); mp_input_get_cmd(mpctx->input, sleeptime * 1000, true); + MP_STATS(mpctx, "end sleep"); + } } handle_metadata_update(mpctx); diff --git a/video/decode/dec_video.c b/video/decode/dec_video.c index 5c75194e75..cb541e6207 100644 --- a/video/decode/dec_video.c +++ b/video/decode/dec_video.c @@ -303,9 +303,11 @@ struct mp_image *video_decode(struct dec_video *d_video, double prev_codec_pts = d_video->codec_pts; double prev_codec_dts = d_video->codec_dts; + MP_STATS(d_video, "start decode video"); + struct mp_image *mpi = d_video->vd_driver->decode(d_video, packet, drop_frame); - //------------------------ frame decoded. -------------------- + MP_STATS(d_video, "end decode video"); if (!mpi || drop_frame) { talloc_free(mpi); |