msg: reinterpret a bunch of message levels

I've decided that MP_TRACE means “noisy spam per frame”, whereas
MP_DBG just means “more verbose debugging messages than MSGL_V”.
Basically, MSGL_DBG shouldn't create spam per frame like it currently
does, and MSGL_V should make sense to the end-user and provide mostly
additional informational output.

MP_DBG is basically what I want to make the new default for --log-file,
so the cut-off point for MP_DBG is if we probably want to know if for
debugging purposes but the user most likely doesn't care about on the
terminal.

Also, the debug callbacks for libass and ffmpeg got bumped in their
verbosity levels slightly, because being external components they're a
bit less relevant to mpv debugging, and a bit too over-eager in what
they consider to be relevant information.

I exclusively used the "try it on my machine and remove messages from
MSGL_* until it does what I want it to" approach of refactoring, so
YMMV.
This commit is contained in:
Niklas Haas 2017-09-28 11:53:57 +02:00 committed by Kevin Mitchell
parent d744dca537
commit ba1943ac00
18 changed files with 69 additions and 86 deletions

View File

@ -64,9 +64,9 @@ static bool log_print_prefix = true;
static int av_log_level_to_mp_level(int av_level)
{
if (av_level > AV_LOG_VERBOSE)
return MSGL_DEBUG;
return MSGL_TRACE;
if (av_level > AV_LOG_INFO)
return MSGL_V;
return MSGL_DEBUG;
if (av_level > AV_LOG_WARNING)
return MSGL_V;
if (av_level > AV_LOG_ERROR)

View File

@ -793,7 +793,7 @@ int encode_lavc_write_frame(struct encode_lavc_context *ctx, AVStream *stream,
if (ctx->header_written <= 0)
return -1;
MP_DBG(ctx,
MP_TRACE(ctx,
"write frame: stream %d ptsi %d (%f) dtsi %d (%f) size %d\n",
(int)packet->stream_index,
(int)packet->pts,

View File

@ -468,7 +468,7 @@ static mp_cmd_t *get_cmd_from_keys(struct input_ctx *ictx, char *force_section,
return mp_input_parse_cmd_strv(ictx->log, (const char*[]){"quit", 0});
int msgl = MSGL_WARN;
if (MP_KEY_IS_MOUSE_MOVE(code))
msgl = MSGL_DEBUG;
msgl = MSGL_TRACE;
char *key_buf = mp_input_get_key_combo_name(&code, 1);
MP_MSG(ictx, msgl, "No key binding found for key '%s'.\n", key_buf);
talloc_free(key_buf);
@ -478,8 +478,8 @@ static mp_cmd_t *get_cmd_from_keys(struct input_ctx *ictx, char *force_section,
if (ret) {
ret->input_section = cmd->owner->section;
ret->key_name = talloc_steal(ret, mp_input_get_key_combo_name(&code, 1));
MP_DBG(ictx, "key '%s' -> '%s' in '%s'\n",
ret->key_name, cmd->cmd, ret->input_section);
MP_TRACE(ictx, "key '%s' -> '%s' in '%s'\n",
ret->key_name, cmd->cmd, ret->input_section);
ret->is_mouse_button = code & MP_KEY_EMIT_ON_UP;
} else {
char *key_buf = mp_input_get_key_combo_name(&code, 1);
@ -501,8 +501,8 @@ static void update_mouse_section(struct input_ctx *ictx)
ictx->mouse_section = new_section;
if (strcmp(old, ictx->mouse_section) != 0) {
MP_DBG(ictx, "input: switch section %s -> %s\n",
old, ictx->mouse_section);
MP_TRACE(ictx, "input: switch section %s -> %s\n",
old, ictx->mouse_section);
mp_input_queue_cmd(ictx, get_cmd_from_keys(ictx, old, MP_KEY_MOUSE_LEAVE));
}
}
@ -561,9 +561,9 @@ static void interpret_key(struct input_ctx *ictx, int code, double scale,
if (mp_msg_test(ictx->log, MSGL_DEBUG)) {
char *key = mp_input_get_key_name(code);
MP_DBG(ictx, "key code=%#x '%s'%s%s\n",
code, key, (state & MP_KEY_STATE_DOWN) ? " down" : "",
(state & MP_KEY_STATE_UP) ? " up" : "");
MP_TRACE(ictx, "key code=%#x '%s'%s%s\n",
code, key, (state & MP_KEY_STATE_DOWN) ? " down" : "",
(state & MP_KEY_STATE_UP) ? " up" : "");
talloc_free(key);
}
@ -708,7 +708,7 @@ static void mp_input_feed_key(struct input_ctx *ictx, int code, double scale,
code = mp_normalize_keycode(code);
int unmod = code & ~MP_KEY_MODIFIER_MASK;
if (code == MP_INPUT_RELEASE_ALL) {
MP_DBG(ictx, "release all\n");
MP_TRACE(ictx, "release all\n");
release_down_cmd(ictx, false);
return;
}
@ -816,7 +816,7 @@ void mp_input_set_mouse_pos(struct input_ctx *ictx, int x, int y)
void mp_input_set_mouse_pos_artificial(struct input_ctx *ictx, int x, int y)
{
input_lock(ictx);
MP_DBG(ictx, "mouse move %d/%d\n", x, y);
MP_TRACE(ictx, "mouse move %d/%d\n", x, y);
if (ictx->mouse_vo_x == x && ictx->mouse_vo_y == y) {
input_unlock(ictx);
@ -832,7 +832,7 @@ void mp_input_set_mouse_pos_artificial(struct input_ctx *ictx, int x, int y)
x = x * 1.0 / (dst->x1 - dst->x0) * (src->x1 - src->x0) + src->x0;
y = y * 1.0 / (dst->y1 - dst->y0) * (src->y1 - src->y0) + src->y0;
}
MP_DBG(ictx, "-> %d/%d\n", x, y);
MP_TRACE(ictx, "-> %d/%d\n", x, y);
}
ictx->mouse_event_counter++;

View File

@ -900,8 +900,8 @@ int m_config_set_option_cli(struct m_config *config, struct bstr name,
goto done;
if (r == 2) {
MP_VERBOSE(config, "Setting option '%.*s' = '%.*s' (flags = %d)\n",
BSTR_P(name), BSTR_P(param), flags);
MP_DBG(config, "Setting option '%.*s' = '%.*s' (flags = %d)\n",
BSTR_P(name), BSTR_P(param), flags);
}
union m_option_value val = {0};
@ -952,8 +952,8 @@ int m_config_set_option_node(struct m_config *config, bstr name,
if (mp_msg_test(config->log, MSGL_V)) {
char *s = m_option_type_node.print(NULL, data);
MP_VERBOSE(config, "Setting option '%.*s' = %s (flags = %d) -> %d\n",
BSTR_P(name), s ? s : "?", flags, r);
MP_DBG(config, "Setting option '%.*s' = %s (flags = %d) -> %d\n",
BSTR_P(name), s ? s : "?", flags, r);
talloc_free(s);
}

View File

@ -98,7 +98,7 @@ char *mp_find_user_config_file(void *talloc_ctx, struct mpv_global *global,
if (res)
res = mp_path_join(talloc_ctx, res, filename);
talloc_free(tmp);
MP_VERBOSE(global, "config path: '%s' -> '%s'\n", filename, res ? res : "-");
MP_DBG(global, "config path: '%s' -> '%s'\n", filename, res ? res : "-");
return res;
}
@ -119,12 +119,12 @@ static char **mp_find_all_config_files_limited(void *talloc_ctx,
char *file = mp_path_join_bstr(ret, bstr0(dir), fn);
if (mp_path_exists(file)) {
MP_VERBOSE(global, "config path: '%.*s' -> '%s'\n",
BSTR_P(fn), file);
MP_DBG(global, "config path: '%.*s' -> '%s'\n",
BSTR_P(fn), file);
MP_TARRAY_APPEND(NULL, ret, num_ret, file);
} else {
MP_VERBOSE(global, "config path: '%.*s' -/-> '%s'\n",
BSTR_P(fn), file);
MP_DBG(global, "config path: '%.*s' -/-> '%s'\n",
BSTR_P(fn), file);
}
}
}
@ -189,7 +189,7 @@ char *mp_get_user_path(void *talloc_ctx, struct mpv_global *global,
}
if (!res)
res = talloc_strdup(talloc_ctx, path);
MP_VERBOSE(global, "user path: '%s' -> '%s'\n", path, res);
MP_DBG(global, "user path: '%s' -> '%s'\n", path, res);
return res;
}

View File

@ -4845,7 +4845,7 @@ int run_command(struct MPContext *mpctx, struct mp_cmd *cmd, struct mpv_node *re
int osdl = msg_osd ? 1 : OSD_LEVEL_INVISIBLE;
bool async = cmd->flags & MP_ASYNC_CMD;
mp_cmd_dump(mpctx->log, cmd->id == MP_CMD_IGNORE ? MSGL_DEBUG : MSGL_V,
mp_cmd_dump(mpctx->log, cmd->id == MP_CMD_IGNORE ? MSGL_TRACE : MSGL_DEBUG,
"Run command:", cmd);
if (cmd->flags & MP_EXPAND_PROPERTIES) {

View File

@ -193,7 +193,7 @@ static void add_functions(struct script_ctx *ctx);
static void load_file(lua_State *L, const char *fname)
{
struct script_ctx *ctx = get_ctx(L);
MP_VERBOSE(ctx, "loading file %s\n", fname);
MP_DBG(ctx, "loading file %s\n", fname);
int r = luaL_loadfile(L, fname);
if (r)
lua_error(L);
@ -222,7 +222,7 @@ static int load_builtin(lua_State *L)
static void require(lua_State *L, const char *name)
{
struct script_ctx *ctx = get_ctx(L);
MP_VERBOSE(ctx, "loading %s\n", name);
MP_DBG(ctx, "loading %s\n", name);
// Lazy, but better than calling the "require" function manually
char buf[80];
snprintf(buf, sizeof(buf), "require '%s'", name);

View File

@ -1902,7 +1902,7 @@ function show_osc()
-- show when disabled can happen (e.g. mouse_move) due to async/delayed unbinding
if not state.enabled then return end
msg.debug("show_osc")
msg.trace("show_osc")
--remember last time of invocation (mouse move)
state.showtime = mp.get_time()
@ -1914,7 +1914,7 @@ function show_osc()
end
function hide_osc()
msg.debug("hide_osc")
msg.trace("hide_osc")
if not state.enabled then
-- typically hide happens at render() from tick(), but now tick() is
-- no-op and won't render again to remove the osc, so do that manually.
@ -1958,7 +1958,7 @@ end
function timer_start()
if not (state.timer_active) then
msg.debug("timer start")
msg.trace("timer start")
if (state.timer == nil) then
-- create new timer
@ -1974,7 +1974,7 @@ end
function timer_stop()
if (state.timer_active) then
msg.debug("timer stop")
msg.trace("timer stop")
if not (state.timer == nil) then
-- kill timer
@ -2000,12 +2000,12 @@ function request_init()
end
function render_wipe()
msg.debug("render_wipe()")
msg.trace("render_wipe()")
mp.set_osd_ass(0, 0, "{}")
end
function render()
msg.debug("rendering")
msg.trace("rendering")
local current_screen_sizeX, current_screen_sizeY, aspect = mp.get_osd_size()
local mouseX, mouseY = get_virt_mouse_pos()
local now = mp.get_time()
@ -2208,7 +2208,7 @@ function tick()
if (state.idle) then
-- render idle message
msg.debug("idle message")
msg.trace("idle message")
local icon_x, icon_y = 320 - 26, 140
local ass = assdraw.ass_new()

View File

@ -140,7 +140,7 @@ int mp_load_script(struct MPContext *mpctx, const char *fname)
}
arg->log = mp_client_get_log(arg->client);
MP_VERBOSE(arg, "Loading %s %s...\n", backend->name, fname);
MP_DBG(arg, "Loading %s %s...\n", backend->name, fname);
pthread_t thread;
if (pthread_create(&thread, NULL, script_thread, arg)) {
@ -150,7 +150,7 @@ int mp_load_script(struct MPContext *mpctx, const char *fname)
}
wait_loaded(mpctx);
MP_VERBOSE(mpctx, "Done loading %s.\n", fname);
MP_DBG(mpctx, "Done loading %s.\n", fname);
return 0;
}

View File

@ -1072,10 +1072,10 @@ static void handle_display_sync_frame(struct MPContext *mpctx,
double prev_error = mpctx->display_sync_error;
mpctx->display_sync_error += frame_duration - num_vsyncs * vsync;
MP_DBG(mpctx, "s=%f vsyncs=%d dur=%f ratio=%f err=%.20f (%f/%f)\n",
mpctx->speed_factor_v, num_vsyncs, adjusted_duration, ratio,
mpctx->display_sync_error, mpctx->display_sync_error / vsync,
mpctx->display_sync_error / frame_duration);
MP_TRACE(mpctx, "s=%f vsyncs=%d dur=%f ratio=%f err=%.20f (%f/%f)\n",
mpctx->speed_factor_v, num_vsyncs, adjusted_duration, ratio,
mpctx->display_sync_error, mpctx->display_sync_error / vsync,
mpctx->display_sync_error / frame_duration);
MP_STATS(mpctx, "value %f avdiff", av_diff);

View File

@ -251,7 +251,7 @@ static int open_internal(const stream_info_t *sinfo, const char *url, int flags,
MP_VERBOSE(s, "Opening %s\n", url);
if ((s->mode & STREAM_WRITE) && !sinfo->can_write) {
MP_VERBOSE(s, "No write access implemented.\n");
MP_DBG(s, "No write access implemented.\n");
talloc_free(s);
return STREAM_NO_MATCH;
}
@ -273,7 +273,7 @@ static int open_internal(const stream_info_t *sinfo, const char *url, int flags,
if (s->mime_type)
MP_VERBOSE(s, "Mime-type: '%s'\n", s->mime_type);
MP_VERBOSE(s, "Stream opened successfully.\n");
MP_DBG(s, "Stream opened successfully.\n");
*ret = s;
return STREAM_OK;

View File

@ -109,8 +109,8 @@ static const int map_ass_level[] = {
MSGL_INFO,
MSGL_V,
MSGL_V,
MSGL_V, // 5 application recommended level
MSGL_DEBUG,
MSGL_DEBUG, // 5 application recommended level
MSGL_TRACE,
MSGL_TRACE, // 7 "verbose DEBUG"
};

View File

@ -870,16 +870,16 @@ static int get_buffer2_direct(AVCodecContext *avctx, AVFrame *pic, int flags)
p->dr_w = w;
p->dr_h = h;
p->dr_stride_align = stride_align;
MP_VERBOSE(p, "DR parameter change to %dx%d %s align=%d\n", w, h,
mp_imgfmt_to_name(imgfmt), stride_align);
MP_DBG(p, "DR parameter change to %dx%d %s align=%d\n", w, h,
mp_imgfmt_to_name(imgfmt), stride_align);
}
struct mp_image *img = mp_image_pool_get_no_alloc(p->dr_pool, imgfmt, w, h);
if (!img) {
MP_VERBOSE(p, "Allocating new DR image...\n");
MP_DBG(p, "Allocating new DR image...\n");
img = vo_get_image(vd->vo, imgfmt, w, h, stride_align);
if (!img) {
MP_VERBOSE(p, "...failed..\n");
MP_DBG(p, "...failed..\n");
goto fallback;
}

View File

@ -260,7 +260,7 @@ static void VS_CC vs_frame_done(void *userData, const VSFrameRef *f, int n,
// If these assertions fail, n is an unrequested frame (or filtered twice).
assert(n >= p->out_frameno && n < p->out_frameno + p->max_requests);
int index = n - p->out_frameno;
MP_DBG(vf, "filtered frame %d (%d)\n", n, index);
MP_TRACE(vf, "filtered frame %d (%d)\n", n, index);
assert(p->requested[index] == &dummy_img);
struct mp_image *res = NULL;
@ -328,7 +328,7 @@ static bool locked_read_output(struct vf_instance *vf)
// infiltGetFrame (if it does, we would deadlock)
p->requested[n] = (struct mp_image *)&dummy_img;
p->failed = false;
MP_DBG(vf, "requesting frame %d (%d)\n", p->out_frameno + n, n);
MP_TRACE(vf, "requesting frame %d (%d)\n", p->out_frameno + n, n);
p->vsapi->getFrameAsync(p->out_frameno + n, p->out_node,
vs_frame_done, vf);
}
@ -463,7 +463,7 @@ static const VSFrameRef *VS_CC infiltGetFrame(int frameno, int activationReason,
VSFrameRef *ret = NULL;
pthread_mutex_lock(&p->lock);
MP_DBG(vf, "VS asking for frame %d (at %d)\n", frameno, p->in_frameno);
MP_TRACE(vf, "VS asking for frame %d (at %d)\n", frameno, p->in_frameno);
while (1) {
if (p->shutdown) {
p->vsapi->setFilterError("EOF or filter reinit/uninit", frameCtx);

View File

@ -144,7 +144,7 @@ void gl_sc_reset(struct gl_shader_cache *sc)
static void sc_flush_cache(struct gl_shader_cache *sc)
{
MP_VERBOSE(sc, "flushing shader cache\n");
MP_DBG(sc, "flushing shader cache\n");
for (int n = 0; n < sc->num_entries; n++) {
struct sc_entry *e = sc->entries[n];
@ -550,15 +550,6 @@ static bool create_pass(struct gl_shader_cache *sc, struct sc_entry *entry)
void *tmp = talloc_new(NULL);
struct ra_renderpass_params params = sc->params;
MP_VERBOSE(sc, "new shader program:\n");
if (sc->header_text.len) {
MP_VERBOSE(sc, "header:\n");
mp_log_source(sc->log, MSGL_V, sc->header_text.start);
MP_VERBOSE(sc, "body:\n");
}
if (sc->text.len)
mp_log_source(sc->log, MSGL_V, sc->text.start);
const char *cache_header = "mpv shader cache v1\n";
char *cache_filename = NULL;
char *cache_dir = NULL;
@ -583,7 +574,7 @@ static bool create_pass(struct gl_shader_cache *sc, struct sc_entry *entry)
cache_filename = mp_path_join(tmp, cache_dir, hashstr);
if (stat(cache_filename, &(struct stat){0}) == 0) {
MP_VERBOSE(sc, "Trying to load shader from disk...\n");
MP_DBG(sc, "Trying to load shader from disk...\n");
struct bstr cachedata =
stream_read_file(cache_filename, tmp, sc->global, 1000000000);
if (bstr_eatstart0(&cachedata, cache_header))
@ -633,7 +624,7 @@ static bool create_pass(struct gl_shader_cache *sc, struct sc_entry *entry)
if (nc.len && !bstr_equals(params.cached_program, nc)) {
mp_mkdirp(cache_dir);
MP_VERBOSE(sc, "Writing shader cache file: %s\n", cache_filename);
MP_DBG(sc, "Writing shader cache file: %s\n", cache_filename);
FILE *out = fopen(cache_filename, "wb");
if (out) {
fwrite(cache_header, strlen(cache_header), 1, out);

View File

@ -181,7 +181,7 @@ bool ra_tex_resize(struct ra *ra, struct mp_log *log, struct ra_tex **tex,
return true;
}
mp_verbose(log, "Resizing texture: %dx%d\n", w, h);
mp_dbg(log, "Resizing texture: %dx%d\n", w, h);
if (!fmt || !fmt->renderable || !fmt->linear_filter) {
mp_err(log, "Format %s not supported.\n", fmt ? fmt->name : "(unset)");

View File

@ -1053,11 +1053,11 @@ static void pass_report_performance(struct gl_video *p)
for (int i = 0; i < VO_PASS_PERF_MAX; i++) {
struct pass_info *pass = &p->pass[i];
if (pass->desc.len) {
MP_DBG(p, "pass '%.*s': last %dus avg %dus peak %dus\n",
BSTR_P(pass->desc),
(int)pass->perf.last/1000,
(int)pass->perf.avg/1000,
(int)pass->perf.peak/1000);
MP_TRACE(p, "pass '%.*s': last %dus avg %dus peak %dus\n",
BSTR_P(pass->desc),
(int)pass->perf.last/1000,
(int)pass->perf.avg/1000,
(int)pass->perf.peak/1000);
}
}
}
@ -1393,8 +1393,8 @@ static bool pass_hook_setup_binds(struct gl_video *p, const char *name,
struct image bind_img;
if (!saved_img_find(p, bind_name, &bind_img)) {
// Clean up texture bindings and move on to the next hook
MP_DBG(p, "Skipping hook on %s due to no texture named %s.\n",
name, bind_name);
MP_TRACE(p, "Skipping hook on %s due to no texture named %s.\n",
name, bind_name);
p->num_pass_imgs -= t;
return false;
}
@ -1425,7 +1425,7 @@ static struct image pass_hook(struct gl_video *p, const char *name,
saved_img_store(p, name, img);
MP_DBG(p, "Running hooks for %s\n", name);
MP_TRACE(p, "Running hooks for %s\n", name);
for (int i = 0; i < p->num_tex_hooks; i++) {
struct tex_hook *hook = &p->tex_hooks[i];
@ -1440,7 +1440,7 @@ static struct image pass_hook(struct gl_video *p, const char *name,
found:
// Check the hook's condition
if (hook->cond && !hook->cond(p, img, hook->priv)) {
MP_DBG(p, "Skipping hook on %s due to condition.\n", name);
MP_TRACE(p, "Skipping hook on %s due to condition.\n", name);
continue;
}
@ -2073,7 +2073,6 @@ static void pass_read_video(struct gl_video *p)
struct mp_rect_f src = {0.0, 0.0, p->image_params.w, p->image_params.h};
struct mp_rect_f ref = src;
gl_transform_rect(p->texture_offset, &ref);
MP_DBG(p, "ref rect: {%f %f} {%f %f}\n", ref.x0, ref.y0, ref.x1, ref.y1);
// Explicitly scale all of the textures that don't match
for (int n = 0; n < 4; n++) {
@ -2084,9 +2083,6 @@ static void pass_read_video(struct gl_video *p)
// exact same source rectangle.
struct mp_rect_f rect = src;
gl_transform_rect(offsets[n], &rect);
MP_DBG(p, "rect[%d]: {%f %f} {%f %f}\n", n,
rect.x0, rect.y0, rect.x1, rect.y1);
if (mp_rect_f_seq(ref, rect))
continue;
@ -2098,8 +2094,6 @@ static void pass_read_video(struct gl_video *p)
{0.0, (ref.y1 - ref.y0) / (rect.y1 - rect.y0)}},
.t = {ref.x0, ref.y0},
};
MP_DBG(p, "-> fix[%d] = {%f %f} + off {%f %f}\n", n,
fix.m[0][0], fix.m[1][1], fix.t[0], fix.t[1]);
// Since the scale in texture space is different from the scale in
// absolute terms, we have to scale the coefficients down to be
@ -2113,8 +2107,6 @@ static void pass_read_video(struct gl_video *p)
MPSWAP(double, scale.m[0][0], scale.m[1][1]);
gl_transform_trans(scale, &fix);
MP_DBG(p, "-> scaled[%d] = {%f %f} + off {%f %f}\n", n,
fix.m[0][0], fix.m[1][1], fix.t[0], fix.t[1]);
// Since the texture transform is a function of the texture coordinates
// to texture space, rather than the other way around, we have to
@ -2998,8 +2990,8 @@ static void gl_video_interpolate_frame(struct gl_video *p, struct vo_frame *t,
assert(id == i);
}
MP_DBG(p, "inter frame dur: %f vsync: %f, mix: %f\n",
t->ideal_frame_duration, t->vsync_interval, mix);
MP_TRACE(p, "inter frame dur: %f vsync: %f, mix: %f\n",
t->ideal_frame_duration, t->vsync_interval, mix);
p->is_interpolated = true;
}
pass_draw_to_screen(p, fbo);
@ -3803,8 +3795,8 @@ void gl_video_set_ambient_lux(struct gl_video *p, int lux)
{
if (p->opts.gamma_auto) {
p->opts.gamma = gl_video_scale_ambient_lux(16.0, 256.0, 1.0, 1.2, lux);
MP_VERBOSE(p, "ambient light changed: %d lux (gamma: %f)\n", lux,
p->opts.gamma);
MP_TRACE(p, "ambient light changed: %d lux (gamma: %f)\n", lux,
p->opts.gamma);
}
}

View File

@ -789,7 +789,7 @@ static GLuint load_program(struct ra *ra, const struct ra_renderpass_params *p,
GLint status = 0;
gl->GetProgramiv(prog, GL_LINK_STATUS, &status);
if (status) {
MP_VERBOSE(ra, "Loading binary program succeeded.\n");
MP_DBG(ra, "Loading binary program succeeded.\n");
} else {
gl->DeleteProgram(prog);
prog = 0;