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.

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);