Req "Demuxer" for separate streams
#16
(2016-01-10, 18:10)peak3d Wrote: On my system its directX and when you decode the first packet ffmpeg sets up the DXVA decoder already at the time the changed packet arrives.

ffmpeg hw accelerators are opened on call of GetFormat. This is done in Open() without the need for decoding.
Reply
#17
On call to open we provide extradata to the codec (SPS). This is all info a codec needs to initialize.
Reply
#18
No, simply place a breakpoint in GetFormat().
You'll see that GetFormat is called from ffmeg at the time the first packet is decoded.

I could also give you logs for this, but you have this debugged in shorter time.

Ah, I forgot that I already posted this in another thread: http://forum.kodi.tv/showthread.php?tid=255628
There is the part of the log - at the time I wote it it was not clear for me - it was after debugging.....

Edit:
https://www.dropbox.com/sh/0tbmofg68ouf3...at5Ja?dl=0
There is the movie, wich changes resolution at exactly 20 secs after start.

In log_with_decode.txt you'll see the DXVA setup 14 secs after start, in the without_decode.txt exactly 20 secs after start.
Reply
#19
Something must have changed. Not good ....
Reply
#20
After some discussions in 8830 (PR)

I changed minor parts in kodi to supress "General Stream Change" syncronization if streams change inbetween.
Unfortunately there is still a short "freeze" of the movie after the change.

Log file is:

https://www.dropbox.com/sh/0tbmofg68ouf3...at5Ja?dl=0
kodi_nosync.log

1.) Video starts at:
16:16:26 T:20356 NOTICE: VideoPlayer: Opening: C:\Temp\muxed.mov

2.) Resolution change is read from Demuxer at:
16:16:38 T:18460 DEBUG: CDVDDemuxFFmpeg::CDVDDemuxFFmpeg::Read - streamId 0 change. Packet-pts: 20010666.6667
(...)
16:16:40 T:18460 DEBUG: CDVDDemuxFFmpeg::CDVDDemuxFFmpeg::Read - streamId 1 change. Packet-pts: 20103416.6667

3.) Resolution Change occurs at:

16:16:46 T:2560 DEBUG: CVideoPlayerAudio: Sample rate changed, checking for passthrough
(...)
16:16:46 T:11256 DEBUG: CRenderManager::Configure - change configuration. 512x288. display: 512x288. framerate: 0.00. format: DXVA

Unfortunately after the succesfull resolution switch there are following log lines:

16:16:46 T:11256 DEBUG: CPullupCorrection: pattern lost on diff 125125.000000, number of losses 1
16:16:46 T:11256 DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

and:

16:16:48 T:2560 DEBUG: CDVDClock:Big Griniscontinuity - CVideoPlayerAudio::OutputPacket - was:21282581.948373, should be:21252309.092819, error:-30272.855554

Somehow I have the feeling that the streamchange without general resync needs some more attention regarding PTS.
Hopefully somebody could lead in the right direction.

I'll make an PR only with this small change in Kodi to give anybody who want to support this the chance to reproduce.
Reply
#21
I finally added milliseconds to the log and changed the initialization of the decoder.
If I read the log right the there is only 1 frame skipped because of the time the Initialization of the renderManager takes:

Code:
22:13:04:0064 T:17368   DEBUG: CVideoPlayerAudio:: synctype set to 0: clock feedback
22:13:04:0412 T:5272   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 10941540
22:13:04:0417 T:5272  NOTICE: DXVA::CDecoder::Close - closing decoder
22:13:04:0425 T:5272   DEBUG: CRenderManager::Configure - change configuration. 512x288. display: 512x288. framerate: 0.00. format: DXVA
22:13:04:0452 T:14696  NOTICE: D3D: rendering method forced to DXVA processor
22:13:04:0457 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Initing Video Enumerator with params: 512x288.
22:13:04:0458 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 3 rate conversion.
22:13:04:0459 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0x2ef feature caps.
22:13:04:0460 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0x1e device caps.
22:13:04:0461 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0 input format caps.
22:13:04:0461 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 8 max input streams.
22:13:04:0462 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 8 max stream states.
22:13:04:0463 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Selected video processor index: 0.
22:13:04:0464 T:14696  NOTICE: DXVA::CProcessorHD::InitProcessor - Supported deinterlace methods: Blend:yes, Bob:yes, Adaptive:yes, MoComp:yes.
22:13:04:0464 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Selected video processor allows 1 future frames and 1 past frames.
22:13:04:0465 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 0 has following params - max: 1000, min: -1000, default: 0
22:13:04:0466 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 1 has following params - max: 1000, min: 0, default: 100
22:13:04:0467 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 2 has following params - max: 1800, min: -1800, default: 0
22:13:04:0467 T:14696   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 3 has following params - max: 1000, min: 0, default: 100
22:13:04:0468 T:14696   DEBUG: DXVA::CProcessorHD::OpenProcessor - Creating processor with input format: (103).
22:13:04:0474 T:14696   DEBUG: CWinRenderer::SelectRenderMethod: Selected render method 3: DXVA
22:13:04:0476 T:14696   DEBUG: created video buffer 0
22:13:04:0476 T:14696   DEBUG: created video buffer 1
22:13:04:0477 T:14696   DEBUG: created video buffer 2
22:13:04:0478 T:14696   DEBUG: created video buffer 3
22:13:04:0478 T:14696   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context
22:13:04:0480 T:14696   DEBUG: created video buffer 4
22:13:04:0481 T:14696   DEBUG: CRenderManager::Configure - 5
22:13:04:0481 T:5272   DEBUG: CPullupCorrection: pattern lost on diff 83417.000000, number of losses 1
22:13:04:0482 T:14696 WARNING: CWinRenderer::UpdateVideoFilter - chosen scaling method 1 is not supported by renderer
22:13:04:0483 T:5272   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1

CPullupCorrection: pattern lost on diff 83417.000000, number of losses 1

Is the sum of frameduration: 41708 and the time wich is taken to startup the renderer.

So my last question is: Is there already a possibility to build up a renderer at the time I know that I will use one in the near future?
Reply
#22
did you wait in RenderManager::Configure until last render buffer was displayed before doing re-configure?
Reply
#23
I have not changed anything in RenderManger so far - but yes there i a locked loop wich waits for it.
disable this for testing?

Edit: would be no good idea, because the images would be not scaled correctly

I'll measure now what this part cost - from feeling I still have a stall from about 0.1 secs also the log says that there is only 1 frame skipped

23:06:36:0467 T:16864 WARNING: CRenderManager::Configure - wait for unfinished start
23:06:36:0501 T:16864 WARNING: CRenderManager::Configure - wait for unfinished end

about 30 msecs
Reply
#24
I think we're not too far away from a solution, because I have the stall after the first frame of the second video part is displayed!
This means for me that the time for the Rendermanger is not the cause, otherwise the first frame would not be displayed so early.

I will add more debug lines now
Reply
#25
Code:
23:45:03:0678 T:5364   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 108AF8A8
23:45:03:0682 T:5364  NOTICE: DXVA::CDecoder::Close - closing decoder
23:45:03:0686 T:5364   DEBUG: CVideoPlayerVideo::Decoding 20020000.000000 - 20103416.666667 - 2
23:45:03:0687 T:5364   DEBUG: CVideoPlayerVideo::Decoding 20061708.333333 - 20270250.000000 - 6
23:45:03:0687 T:5364   DEBUG: CRenderManager::Configure - change configuration. 512x288. display: 512x288. framerate: 0.00. format: DXVA
23:45:03:0688 T:5364 WARNING: CRenderManager::Configure - wait for unfinished start
23:45:03:0718 T:5364 WARNING: CRenderManager::Configure - wait for unfinished end
23:45:03:0721 T:16168  NOTICE: D3D: rendering method forced to DXVA processor
23:45:03:0724 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Initing Video Enumerator with params: 512x288.
23:45:03:0724 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 3 rate conversion.
23:45:03:0725 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0x2ef feature caps.
23:45:03:0725 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0x1e device caps.
23:45:03:0725 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 0 input format caps.
23:45:03:0725 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 8 max input streams.
23:45:03:0726 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Video processor has 8 max stream states.
23:45:03:0726 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Selected video processor index: 0.
23:45:03:0726 T:16168  NOTICE: DXVA::CProcessorHD::InitProcessor - Supported deinterlace methods: Blend:yes, Bob:yes, Adaptive:yes, MoComp:yes.
23:45:03:0727 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Selected video processor allows 1 future frames and 1 past frames.
23:45:03:0727 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 0 has following params - max: 1000, min: -1000, default: 0
23:45:03:0727 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 1 has following params - max: 1000, min: 0, default: 100
23:45:03:0727 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 2 has following params - max: 1800, min: -1800, default: 0
23:45:03:0728 T:16168   DEBUG: DXVA::CProcessorHD::InitProcessor - Filter 3 has following params - max: 1000, min: 0, default: 100
23:45:03:0728 T:16168   DEBUG: DXVA::CProcessorHD::OpenProcessor - Creating processor with input format: (103).
23:45:03:0732 T:16168   DEBUG: CWinRenderer::SelectRenderMethod: Selected render method 3: DXVA
23:45:03:0732 T:16168   DEBUG: created video buffer 0
23:45:03:0733 T:16168   DEBUG: created video buffer 1
23:45:03:0733 T:16168   DEBUG: created video buffer 2
23:45:03:0733 T:16168   DEBUG: created video buffer 3
23:45:03:0734 T:16168   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context
23:45:03:0735 T:16168   DEBUG: created video buffer 4
23:45:03:0736 T:16168   DEBUG: CRenderManager::Configure - 5
23:45:03:0736 T:5364   DEBUG: CPullupCorrection: pattern lost on diff 83417.000000, number of losses 1
23:45:03:0737 T:16168 WARNING: CWinRenderer::UpdateVideoFilter - chosen scaling method 1 is not supported by renderer
23:45:03:0737 T:5364   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
23:45:03:0742 T:5364   DEBUG: Previous line repeats 1 times.
23:45:03:0743 T:5364   DEBUG: CVideoPlayerVideo::Decoding 20103416.666667 - 20186833.333333 - 6
23:45:03:0744 T:5364   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
23:45:03:0746 T:5364   DEBUG: Previous line repeats 1 times.
23:45:03:0747 T:5364   DEBUG: CVideoPlayerVideo::Decoding 20145125.000000 - 20145125.000000 - 6

> 23:45:03:0686 T:5364 DEBUG: CVideoPlayerVideo:Big Grinecoding 20020000.000000 - 20103416.666667 - 2
is the first frame of the second set - it is decded before RenderManger is reinitialized.
The values are dts / pts / result from decode() call

The following frames are decoded after the initialization.

Waiting for a few decoded frames before switching resolution could maybe help??
Reply
#26
In order to rule out dxva traits I suggest to switch this off and use sw decoding with pixel shaders. Once this is working you can go back to dxva.
Reply
#27
From timing its not the big difference if I use SW rendering, but there is again a black frame now (I'll look for it).
It seems that the blocking Renderer finalization and the therefore paused decoding leads to the gap.

For me a reasonable solution would be a similar concept in Renderer as in VideoPlayerVideo:
Attach a reference to the configuration to every picture and let the renderer decide when it switches configuration.

Some other possibilities would be:
a) Build up early new RenderManager at the time we detect the change
b) Build up early a new Renderer in RenderManager (not checked if it could make sense)
c) Build up early a new Processor in Renderer (not checked if it could make sense)
d) and some more

All steps above (a-d) would cause a a lot of programming changes in the existing workflow (sync old and new RM for example).
Because of that for me the initial solution (Renderer decides when to reconfigure) is my favorite so far.

What do you think?

Code:
09:10:03:0633 T:18608   DEBUG: CVideoPlayerVideo::Decoding 19978291.666667 - 20020000.000000 - 6
09:10:03:0675 T:18608   DEBUG: DXVA::CDecoder::~CDecoder - destructing decoder, 1084CA90
09:10:03:0680 T:18608   DEBUG: DXVA::CSurfaceContext::~CSurfaceContext - destructing surface context
09:10:03:0682 T:18608  NOTICE: DXVA::CDecoder::Close - closing decoder
09:10:03:0687 T:18608   DEBUG: CVideoPlayerVideo::Decoding 20020000.000000 - 20103416.666667 - 2
09:10:03:0687 T:18608   DEBUG: CVideoPlayerVideo::Decoding 20061708.333333 - 20270250.000000 - 6
09:10:03:0688 T:18608   DEBUG: CRenderManager::Configure - change configuration. 512x288. display: 512x288. framerate: 0.00. format: DXVA
09:10:03:0688 T:18608 WARNING: CRenderManager::Configure - wait for unfinished start
09:10:03:0713 T:18608 WARNING: CRenderManager::Configure - wait for unfinished end
09:10:03:0715 T:8956   DEBUG: CWinRenderer::SelectRenderMethod: Requested render method: 3
09:10:03:0715 T:8956   DEBUG: CWinRenderer::SelectRenderMethod: Selected render method 2: Software
09:10:03:0716 T:8956   DEBUG: created video buffer 0
09:10:03:0717 T:8956   DEBUG: created video buffer 1
09:10:03:0717 T:8956   DEBUG: created video buffer 2
09:10:03:0717 T:8956   DEBUG: CRenderManager::Configure - 3
09:10:03:0718 T:18608   DEBUG: CPullupCorrection: pattern lost on diff 83417.000000, number of losses 1
09:10:03:0719 T:18608   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
09:10:03:0727 T:18608   DEBUG: Previous line repeats 1 times.
09:10:03:0728 T:18608   DEBUG: CVideoPlayerVideo::Decoding 20103416.666667 - 20186833.333333 - 6
09:10:03:0729 T:8956   DEBUG: CWinRenderer::CreateIntermediateRenderTarget: format 87
09:10:03:0730 T:18608   DEBUG: CVideoPlayerVideo::CalcDropRequirement - hurry: 1
09:10:03:0731 T:18608   DEBUG: Previous line repeats 1 times.
09:10:03:0731 T:18608   DEBUG: CVideoPlayerVideo::Decoding 20145125.000000 - 20145125.000000 - 6
Reply
#28
(2016-01-12, 10:34)peak3d Wrote: From timing its not the big difference if I use SW rendering,

Don't mix this up. Never ever use sw rendering. This mode will be removed soon. I was talking about sw decoding.
Reply
#29
(2016-01-12, 10:34)peak3d Wrote: a) Build up early new RenderManager at the time we detect the change
b) Build up early a new Renderer in RenderManager (not checked if it could make sense)
c) Build up early a new Processor in Renderer (not checked if it could make sense)
d) and some more

none of those would work. there can only be one renderer. video player thread should not be blocked in configure
Reply
#30
(2016-01-12, 11:39)FernetMenta Wrote:
(2016-01-12, 10:34)peak3d Wrote: From timing its not the big difference if I use SW rendering,

Don't mix this up. Never ever use sw rendering. This mode will be removed soon. I was talking about sw decoding.

I'm lost :-( RenderMethod pixel-shader do not affects the decoding.
I have the possibility to select RenderMethod pixel-shader and / or disable H/W decoding.

I was sure that you mean RenderMethod pixel-shader (wich doesn't crash but has a black frame also)
Reply

Logout Mark Read Team Forum Stats Members Help
"Demuxer" for separate streams1
This forum uses Lukasz Tkacz MyBB addons.