Linux: measure encoding time per frame (intended for AMD users)

[gschintgen]

Description

This commit adds detailed debug output measuring the exact time it takes to encode each video frame. It is intended to diagnose issues with AMD encoding in Linux (via ffmpeg and VA-API). Its usefulness for other encoders might be limited and the output is rather verbose. Thus it might not be adequate for merging as-is, but it would be very helpful to have pre-built binaries available for users that want to investigate the current situation and maybe even participate in reporting the issue(s) upstream.

Example output:

[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 771, 3.10952                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 772, 2.95359                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 773, 3.1174                                                         
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 774, 3.0117                                                         
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 775, 5.73846                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 776, 5.64102                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 777, 5.68458                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 778, 5.64336                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 779, 5.79077                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 780, 3.03185                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 781, 3.35225                                                        
[2024:04:13:21:21:13]: Debug: Frame number, encoding time (ms): 782, 3.01634                                                        

A .csv file for easier analysis can be created using the following command:

grep "encoding time" .config/sunshine/sunshine.log | awk '{print $(NF-1)$NF}' > sunshine.csv

There are two reports/discussions about very similar, if not identical, problems with AMD under Linux:
https://github.com/LizardByte/Sunshine/discussions/2193 (RDNA2 cards)
The commit is obviously based on @kodemeister 's idea/code.
https://github.com/LizardByte/Sunshine/discussions/2348 (RDNA3 cards)

Screenshot

Issues Fixed or Closed

Type of Change

• Bug fix (non-breaking change which fixes an issue)
• New feature (non-breaking change which adds functionality)
• Breaking change (fix or feature that would cause existing functionality to not work as expected)
• Dependency update (updates to dependencies)
• Documentation update (changes to documentation)
• Repository update (changes to repository files, e.g. .github/...)

Checklist

• My code follows the style guidelines of this project
• I have performed a self-review of my own code
• I have commented my code, particularly in hard-to-understand areas
• I have added or updated the in code docstring/documentation-blocks for new or existing methods/components

Branch Updates

LizardByte requires that branches be up-to-date before merging. This means that after any PR is merged, this branch
must be updated before it can be merged. You must also
Allow edits from maintainers.

• I want maintainers to keep my branch updated

[gschintgen]

I'm closing this PR since the original issue has been properly upstreamed and diagnosed.
See https://gitlab.freedesktop.org/drm/amd/-/issues/3336

[ReenigneArcher]

Even though the reason for the debug logging has been fixed upstream, we could still consider this.

But perhaps the start/end should only be evaluated if in debug mode?

[gschintgen]

The problem with this logging change is that it is enormously verbose: 60 (or even 120...) lines per second. I think having this much logging would just pollute the debug level too much. Also: the "host processing latency" on Moonlight's side shows essentially the same numbers. A summary (min/max/avg) is also emitted to Sunshine's log every 20 seconds at loglevel debug. In essence the PR is mostly useful to generate detailed timing graphs from .csv files...

I could move it to verbose loglevel, but that one is already shockingly detailed.

At this point I'd say that for AMD users it'd be more useful to point out the issue in the Troubleshooting section in the official documentation. And maybe, for the adventurous users, point to a few resources on how to build a patched mesa. (I rebuilt mesa from ubuntu source debs, but need to do some validation and write it up succinctly.) Unfortunately it could take quite some time until this will be properly fixed (i.e. by changes to upstream libva.) There are also a few other rough edges that could profit from a bit more documentation. (I'll look into it, time permitting.)

It could also be interesting to maybe encode on an Intel iGPU even though AMD is used to render and capture. (Currently this only works for x11grab, but not with KMS. I just checked that this evening. #2053 should implement it though.) But that's probably not the best approach anyway for high bandwidth configurations like 4k@120Hz.