mpv-player / mpv

🎥 Command line video player
https://mpv.io
Other
27.84k stars 2.87k forks source link

mid playback "[vo/gpu-next/libplacebo] Spent 98.917 ms translating GLSL to SPIR-V" cause frames to drop #12221

Closed mitzsch closed 1 year ago

mitzsch commented 1 year ago

Important Information

Provide following Information:

Reproduction steps / Explanation

It is somewhat difficult to reproduce. I opened this as an issue but it is also a question. Let me explain what's going on. I recently watched a 1080p movie and normally it only drops some frames at the beginning of playback. That is expected I guess and not a problem at all, but this time after 6 or 7 minutes I noticed another frame drop of about two frames and looked directly in the log. There I saw this line being printed: [vo/gpu-next/libplacebo] Spent 98.917 ms translating GLSL to SPIR-V. After digging through the other part of the log I found the usual "translating" lines, right after the files playback started. (Spent xxx ms translating HLSL to DXBC) That's how I was used to it. I was also not able to reproduce the frame drop. At first, I thought it was due to pgs subtitles being played at that spot, but there were no "translating" messages after rewatching the same spot. I also deleted the "libplacebo.cache" file. Then the "translating x to x line" was present again, but the time spent on doing so was only a fraction and therefore not interrupting playback. I also had the same behavior on a different file (a 4KHDR file) a while ago... out of nowhere, it was translating x to x - 20 minutes into playback, which caused many frames to be dropped. It was also happening without anything visible or going on (no subtitles, no ui open...). It also not happening on all files, only sometimes... The CPU/GPU should be more than fast enough => Ryzen 5 5500 and Nvidia RTX3050

That's where my question lies... What do they mean? Are these shaders? Used for what? What is causing the "mid-playback" translation of those shaders? Why does it take almost 100ms one time and only 40 next time? Why aren't they all created at the beginning of the playback?

And the underlying issue... Translating those shaders cause some severe frame dropping.

mpv command: mpv.com file.mkv vo=gpu-next -hwdec=d3d11va -swapchain-depth=1 -audio-spdif=ac3 -v

Thanks!

Expected behavior

Generate/Translate all shaders (?) at the beginning of the file.

Actual behavior

Some shaders are generated at the start of playback and some after x minutes which often cause severe frame drops.

Log file

I will try to gather some, if they are needed.

Sample files

/

haasn commented 1 year ago

If you can reproduce it with -v -v it should print the shader it's compiling to trigger the change. Then we can figure out why it's happening randomly for you.

mitzsch commented 1 year ago

If you can reproduce it with -v -v it should print the shader it's compiling to trigger the change. Then we can figure out why it's happening randomly for you.

Thanks for your answer. I tried to reproduce it on my main PC. (Ryzen 5 5600X/RTX3060Ti) And to my surprise, it was very easy.

First log: Starting playback, changing subtitles, and then letting it play, I skipped to a point around 20s pre shader creation [vo/gpu-next/libplacebo] Spent 68.944 ms translating GLSL to SPIR-V log-shader-creation.txt

Second log: Only a small portion of the log, shows how it is reusing that shader log-shader-creation-reuse.txt

Third log: libplacebo.cache deleted, Starting playback, changing subtitles, and then letting it play, I skipped to a point around 20s pre shader creation - this time way faster? log-shader-creation-deleted-cache-new-but-faster.txt

=> Without the subtitle being on, it's not showing a shader creation message (nor does the debug info) at all. So I guess with this one it's related to the subtitles? This seems weird as other files with pgs subs don't show such behavior.


I also could find the spot in the 4K File I mentioned. There it seems to be different. Log: log-shader-creation_4K_file.txt

Do you have a clue what could be going on there?

(edit: you may notice that I´m using a self compiled version of mpv with modifications to ffmpeg (only changing something regarding trueHD passthrough, so should be irrelevant for this test) and mpv (merged player/command: Added ability to scale overlay.) - I just did a quick retest with "plain upstream" mpv and the behavior is the same)

haasn commented 1 year ago

The offending shader recompilation (from your first log):

#version 450
#extension GL_ARB_texture_gather : enable
layout(binding=0) uniform  sampler2D _2;
layout(location=1) in vec2 _5;
layout(location=0) out vec4 out_color;
#define pos _4
#define coord _5

vec4 _1() {
    // overlay
    vec4 color = textureLod(_2, coord, 0.0);
    // pl_shader_decode_color
    {
        if (color.a > 1e-6)
            color.rgb /= vec3(color.a);
    }
    // pl_shader_encode_color
    {
    }
    vec4 _3 = color;
    color = vec4(0.0, 0.0, 0.0, 1.0);
    color[0] = _3[0];
    color[1] = _3[1];
    color[2] = _3[2];
    color.a = _3.a;
    return color;
}

void main() {
    out_color = _1();
}

The earlier overlay shader looks like this:

#version 450
#extension GL_ARB_texture_gather : enable
layout(binding=0) uniform  sampler2D _2;
layout(location=1) in vec2 _5;
layout(location=2) in vec4 _6;
layout(location=0) out vec4 out_color;
#define pos _4
#define coord _5
#define osd_color _6

vec4 _1() {
    // overlay
    vec4 color = osd_color;
    // pl_shader_decode_color
    {
    }
    // pl_shader_encode_color
    {
    }
    color.a *= textureLod(_2, coord, 0.0).r;
    vec4 _3 = color;
    color = vec4(0.0, 0.0, 0.0, 1.0);
    color[0] = _3[0];
    color[1] = _3[1];
    color[2] = _3[2];
    color.a = _3.a;
    return color;
}

void main() {
    out_color = _1();
}

So your theory is correct, and this is caused by the display of PGS subtitles, which are presented as RGB textures (instead of the monochrome alpha textures used by ASS/OSD). There is fundamentally no way around the need to compile this separate shader at some point. So, avenues of improvement are:

  1. Use a shader cache (which should be the default unless you specifically disabled it), to prevent this from happening in the future.
  2. Somehow coax mpv/libplacebo to pre-compile the RGB overlay shader when using PGS subtitles (unfortunately, tricky to accomplish)
  3. Switch to a system where compilation of such a basic shader does not require 70 ms 🤡
kasper93 commented 1 year ago

Switch to a system where compilation of such a basic shader does not require 70 ms 🤡

It's platform agnostic step 🙃

[vo/gpu-next/libplacebo] Spent 68.944 ms translating GLSL to SPIR-V
mitzsch commented 1 year ago

It's platform agnostic step 🙃

So this is a Windows issue?

2. Somehow coax mpv/libplacebo to pre-compile the RGB overlay shader when using PGS subtitles (unfortunately, tricky to accomplish)

Thanks for your answer! But how is this accomplishable?

3. Switch to a system where compilation of such a basic shader does not require 70 ms

Well :D I mean sometimes it's only taking some milliseconds and then the next time 70+. Does it help to run mpv with higher priority?


Do you have a clue what is going on with the 4K file? There are no subtitles involved... but it's also compiling shaders

haasn commented 1 year ago

Well :D I mean sometimes it's only taking some milliseconds and then the next time 70+. Does it help to run mpv with higher priority?

It's definitely possible that the scheduler is fucking up, yeah. I've never seen random spikes like this...

Do you have a clue what is going on with the 4K file? There are no subtitles involved... but it's also compiling shaders

I'll have a look at it later.

kasper93 commented 1 year ago

So this is a Windows issue?

No, the translation to SPIR-V is done always and not related to operating system. Expect for OpenGL, where we use GLSL directly.

Well :D I mean sometimes it's only taking some milliseconds and then the next time 70+. Does it help to run mpv with higher priority?

Since you are using hwdec, your CPU is almost idle during playback. So sudden shader compilation might not ramp up the clocks fast enough. But I wouldn't expect that from desktop CPU, on mobile it sometimes happens, where there is aggressive power management and big.LITTLE like architecture. You may end up compiling on small core which are often order of magnitude slower.

But on Ryzen 5 5500? It is hard to explain why it takes so long sometimes for such basic shader.

Would it be possible to compile libplacebo with -Dshaderc=disabled -Dglslang=enabled? If it makes a difference for you?

mitzsch commented 1 year ago

Would it be possible to compile libplacebo with -Dshaderc=disabled -Dglslang=enabled? If it makes a difference for you?

I will try to recompile it with those parameters set and will retest this! I will report back! thanks!

haasn commented 1 year ago

Do you have a clue what is going on with the 4K file? There are no subtitles involved... but it's also compiling shaders

It looks like it switches from HDR passthrough to HDR tone mapping. If you are using dynamic HDR peak detection, it probably didn't need to tone-map at the beginning of this clip because it was dark enough be playable as-is (without tone-mapping). But then I'm guessing the stutter happened when it switched to a bright scene and suddenly needed to perform tone-mapping.

Again, there's not much that can be done about this case other than somehow pre-generating a tone mapping shader if the source might contain material that needs to be tone-mapped. But I'm not too keen on this.

I think the better solution for you honestly is to just enable the GLSL shader cache and then the issue will solve itself over time. (It's on by default in recent versions of mpv)

mitzsch commented 1 year ago

Thanks for the response!

Very interesting - so it is switching from HDR passthrough to HDR tone mapping? What could be the reason for such behavior? Is the file broken? HDR passthrough however still seems to work, I checked back with my hdfury arcana while hitting that spot in the file. The arcana still showed an active hdr metadata hdmi feed... (for example, when mpv isn´t the active window, the arcana shows that the metadata is not "valid" anymore - so it seems mpv is still passing through all the values correctly...)

I think the better solution for you honestly is to just enable the GLSL shader cache and then the issue will solve itself over time. (It's on by default in recent versions of mpv)

I was only deleting the cache for testing purposes - I will now leave the file as is. I also did some further testing - Unfortunately, I was not able to compile libplacebo with glslang - found out it would be way above my skills to do so... However, I did experiment with Windows priority settings and luckily found out that mpv features a configurable option for changing it directly. With it set to --priority=high shader creation was always that fast, that it hasn't interrupted playback... (more CPU resources are allocated to mpv? - so the CPU is not bored while playback with hw decoding anymore).
I will now run mpv with --priority=high if it's crucial for me to have zero dropped frames. (no idea if that really helps - while testing I was not able to reproduce the issue again..)

haasn commented 1 year ago

Very interesting - so it is switching from HDR passthrough to HDR tone mapping? What could be the reason for such behavior? Is the file broken?

Quite possibly, the file contains a scene with source brightness values above the advertised mastering metadata peak. In HDR passthrough mode, we forward the static HDR10 mastering metadata to the display, in this case 1000 nits. So we assume the display is cutting off everything above 1000 nits.

If a scene with source peak above 1000 nits comes along, we have no choice but to tone-map it to the 1000 nit target. In this case I'd say the file is broken, yeah, the source should never exceed the peak brightness it was mastered to. (Unless we're talking about something annoying like rounding errors causing it to be measured as 1001 nits instead of 1000 nits, which would be enough of a difference to trip the tone-mapper unfortunately...)

Of course, if you have a HDR display with known target peak (e.g. 4000 nits), then this can still happen for completely legitimate files simply based on whether or not the source peak happens to exceed 4000 nits or not.

mitzsch commented 1 year ago

Hmm okay, but something I don´t understand is the additional processing/peak detection. I was under the assumption that running mpv.com file.mkv -vo=gpu-next -target-colorspace-hint=yes only forwards the metadata and nothing else (no additional processing, no peak detection, no heavy lifting of any sort) - So for example on that 4K file let all parts above the mastered and stored nits values clip - if that is what the mastering studio wanted... BluRay players for example don´t alter or fix the stream, arent they? Or is this a misassumption on my side?

Is this "unaltered HDR passthrough playback" even possible with mpv? Should I set it --hdr-compute-peak= to no?

Sorry for all the questions, I´m kinda confused right now...

haasn commented 1 year ago

Hmm okay, but something I don´t understand is the additional processing/peak detection. I was under the assumption that running mpv.com file.mkv -vo=gpu-next -target-colorspace-hint=yes only forwards the metadata and nothing else (no additional processing, no peak detection, no heavy lifting of any sort) - So for example on that 4K file let all parts above the mastered and stored nits values clip - if that is what the mastering studio wanted... BluRay players for example don´t alter or fix the stream, arent they? Or is this a misassumption on my side?

Is this "unaltered HDR passthrough playback" even possible with mpv? Should I set it --hdr-compute-peak= to no?

Sorry for all the questions, I´m kinda confused right now...

Oh, yes, actually, you're right - peak detection is not active on this sample. Now I'm even more confused. Can you check the stats page 2 to see what peak it's actually tone-mapping from and to?

mitzsch commented 1 year ago

Page 2 A few seconds before the spot image

when shader creation happened image

A few seconds after shader creation image

Interesting, where it is getting that 1375 nits value from...

MediaInfo of that file:

Video
ID                                       : 1
ID in the original source medium         : 4113 (0x1011)
Format                                   : HEVC
Format/Info                              : High Efficiency Video Coding
Format-Profil                            : Main 10@L5.1@High
HDR format                               : Dolby Vision, Version 1.0, dvhe.07.06, BL+EL+RPU, Blu-ray compatible / SMPTE ST 2086, HDR10 compatible
Codec-ID                                 : V_MPEGH/ISO/HEVC
Dauer                                    : 1 h 56 min
Bitrate                                  : 55,8 Mb/s
Breite                                   : 3 840 Pixel
Höhe                                     : 2 160 Pixel
Bildseitenverhältnis                     : 16:9
Modus der Bildwiederholungsrate          : konstant
Bildwiederholungsrate                    : 23,976 (24000/1001) FPS
Color space                              : YUV
Chroma subsampling                       : 4:2:0 (Type 2)
Bit depth                                : 10 bits
Bits/(Pixel*Frame)                       : 0.281
Stream-Größe                             : 45,6 GiB (88%)
Sprache                                  : Englisch
Default                                  : Nein
Forced                                   : Nein
Color range                              : Limited
Color primaries                          : BT.2020
Transfer characteristics                 : PQ
Matrix coefficients                      : BT.2020 non-constant
Mastering display color primaries        : Display P3
Mastering display luminance              : min: 0.0001 cd/m2, max: 1000 cd/m2
Maximum Content Light Level              : 997 cd/m2
Maximum Frame-Average Light Level        : 81 cd/m2
Originales Source-Medium                 : Blu-ray
haasn commented 1 year ago

It might be dynamically changing static HDR10 metadata on that particular frame. (You could check with ffprobe -show_frames)

Though, that wouldn't explain this completely, because we propagate static metadata to the display with --target-colorspace-hint per-frame, so we should be getting back the 1375 nits peak from the swapchain for this frame.

mitzsch commented 1 year ago

It might be dynamically changing static HDR10 metadata on that particular frame. (You could check with ffprobe -show_frames)

Though, that wouldn't explain this completely, because we propagate static metadata to the display with --target-colorspace-hint per-frame, so we should be getting back the 1375 nits peak from the swapchain for this frame.

Hmm, maybe something is wrong with that file. I tried ffprobe -show_frames on that file but that didn´t yield anything wrong. ffprobe-out-2.txt I created a small sample containing that spot from that movie* If you like I can send you this sample via email or so.

haasn commented 1 year ago

I see that this clip contains dolby vision RPU metadata. If you're using libplacebo with libdovi enabled, then it's entirely possible that the 1375 nits value comes from the MaxPQ field in the actual dovi RPU (level1 extension block). ffprobe wouldn't show this, as ffmpeg doesn't currently support parsing dovi rpu extension blocks.

cc @quietvoid

quietvoid commented 1 year ago

A sample file would be useful. The Dolby Vision RPU metadata does have source_max_pq=3696 (4000 nits mastering display). IIRC that value overrides the actual HDR10 metadata.

There shouldn't be mid-scene brightness changes, though.

kasper93 commented 1 year ago

source_max_pq=3696 (4000 nits mastering display). IIRC that value overrides the actual HDR10 metadata.

Interesting, so HDR10 1000 nits is kinda backward compatibility for static TM? And we get values >1000 nits from dynamic metadata resulting in the need to tonemap.

I think not much we can do, unless we have API to signal DV. (Windows can do it, but it is not public API) If we go over reported HDR10 max luminance, we have to engage tonemapping.

Good thing the shader compilation will happen only once and is cached.

mitzsch commented 1 year ago

A sample file would be useful.

https://we.tl/t-ScNeznA1ku

I also rechecked what the hdfury arcana says during that spot - the metadata does not change - while hitting that spot it stays at maxLum: 1000nits / minLum: 0.0001nits / maxCLL: 997nits / maxFALL: 81nits

kasper93 commented 1 year ago

RPU plot: L1_plot

I also rechecked what the hdfury arcana says during that spot - the metadata does not change - while hitting that spot it stays at maxLum: 1000nits / minLum: 0.0001nits / maxCLL: 997nits / maxFALL: 81nits

Yes, because libplacebo signals only static HDR10 metadata. In plplay we have a mode that sends dynamic metadata too, but it is not implemented in mpv. And it is unknown if it is even good idea.

@quietvoid @haasn Do you think it is worth adding experimental feature to mpv to send dynamic metadata as HDR10 to display?

haasn commented 1 year ago

Probably worth adding, if the display can handle it it would be beneficial to do. But keep it off by default, because I'm sure many displays shit themselves when changing metadata per-frame.

haasn commented 1 year ago

Anyway, that means we now fully understand what's going on here - dynamic metadata exceeds static mastering metadata, we only signal latter to display, so when the former comes along it forces us to tone-map.

Nothing we can do, shoot sample author.

quietvoid commented 1 year ago

dynamic metadata exceeds static mastering metadata

How come it's still 1000 nits when hdr.max_luma is set from AVDOVIColorMetadata.source_max_pq ? Or is it not here? I thought it should be detected as 4000 nits static, so 1375 nits from the dynamic metadata shouldn't be exceeding it.

haasn commented 1 year ago

dynamic metadata exceeds static mastering metadata

How come it's still 1000 nits when hdr.max_luma is set from AVDOVIColorMetadata.source_max_pq ? Or is it not here? I thought it should be detected as 4000 nits static, so 1375 nits from the dynamic metadata shouldn't be exceeding it.

Seems like --target-colorspace-hint goes through get_mpi_csp which doesn't call pl_frame_map_avdovi_metadata. Improvements welcome. Probably easiest would be to restructure the logic in draw_frame to do the pl_queue_update() before pl_swapchain_start_frame(), and then do the hint based on the frame received from the pl_queue - since that will be mapped properly including the dovi rpu. (This would avoid duplication of logic also)

mitzsch commented 1 year ago

Dumb question on my side, I thought only some DV profiles are handled by mpv and those found on uhd blurays are not... Was this added? Is it possible to ignore those DV bits? Then the problem should also vanish?

quietvoid commented 1 year ago

I thought only some DV profiles are handled by mpv and those found on uhd blurays are not... Was this added? Is it possible to ignore those DV bits? Then the problem should also vanish?

Only the dynamic brightness metadata is used. As far as I can tell it can still only be disabled by using --vf=format:dolbyvision=no.

mitzsch commented 1 year ago

Ah yes! --vf=format:dolbyvision=no did the trick, with this one set it's not creating shaders anymore at that spot. It also does not show the "1375 -> 1000 tone map value".... Thanks!

May I ask how useful only the dynamic brightness metadata is, on top of a HDR10 base layer?

quietvoid commented 1 year ago

It's very useful to have dynamic metadata when hdr-compute-peak is disabled. Though the higher the target display's brightness, the less necessary it becomes.

At 1000 nits target, it won't make much difference at all for 99.9% of the content out there (that is graded below 1000 nits).

mitzsch commented 1 year ago

Okay, I see, but how useful is it for plain passthrough (=> only having -target-colorspace-hint set)? Wouldn´t it make sense to disable the processing of the DV bits for passthrough and only have it enabled when the user requests tone mapping? :)

Anyways thanks to all! :)

quietvoid commented 1 year ago

Wouldn´t it make sense to disable the processing of the DV bits for passthrough and only have it enabled when the user requests tone mapping?

I'm not sure what settings must be set to be considered "plain passthrough", it's a bit confusing to me. I think target-colorspace-hint is required for HDR mode currently, and I don't know how feasible it is to verify that no other params were passed.