2016-01-10, 19:49
2016-01-10, 19:52
On call to open we provide extradata to the codec (SPS). This is all info a codec needs to initialize.
2016-01-10, 21:14
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.
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.
2016-01-11, 08:10
Something must have changed. Not good ....
2016-01-11, 17:40
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:
iscontinuity - 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.
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:
iscontinuity - CVideoPlayerAudio::OutputPacket - was:21282581.948373, should be:21252309.092819, error:-30272.855554Somehow 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.
2016-01-11, 23:29
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:
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?
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: 1CPullupCorrection: 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?
2016-01-11, 23:57
did you wait in RenderManager::Configure until last render buffer was displayed before doing re-configure?
2016-01-12, 00:03
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
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
2016-01-12, 00:27
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
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
2016-01-12, 00:51
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:
ecoding 20020000.000000 - 20103416.666667 - 2is 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??
2016-01-12, 09:52
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.
2016-01-12, 10:34
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?
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
2016-01-12, 11:39
2016-01-12, 11:42
(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
2016-01-12, 11:59
(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)
