search

MythTV / mythtv

The official MythTV repository
https://www.mythtv.org
GNU General Public License v2.0
708 stars 346 forks source link

FashionTV (4k HEVC Sat TV channel) fails to record after g84a9131 #650

Closed warpme closed 2 years ago

warpme commented 2 years ago

What steps will reproduce the bug?

record on FashionTV (4k HEVC Sat TV channel)

How often does it reproduce? Is there a required condition?

always

What is the expected behaviour?

correct recoding

What do you see instead?

Additional information

This is known regression introduced by 84a913147c13092ca6b1e39df18f15d064cceb14

examplery failed recording file: http://warped.inet2.org/fashiontv-failed1.ts http://warped.inet2.org/fashiontv-failed2.ts exemplary good recording file (before 84a913147c): http://warped.inet2.org/fashiontv-good.ts

pls let me know if any other logs/captures are required to move forward with this regression

jpoet commented 2 years ago

Hey Piotr, I guess I missed part of what you were saying about this.... Are you saying the resulting recording file is damaged by these changes? I thought it was just a problem with the seektable. In theory, the resulting recording files should never vary as the bytes are just being written to the disk. The only thing that is being processed is the location of keyframes and metadata.

warpme commented 2 years ago

John,

Yes. To confirm - when I apply https://github.com/warpme/minimyth2/blob/master/script/myth-master/mythtv/files/0060-ticket460-revert-ulmus-scott-fix_BitReader.patch (patch just reverts essential change of #642 on backend) - recording from FassionTV return to be ok.

btw: "broken seektable" was my hypothesis after just brief testing i done with livetv at times i was initially testing on #642 and provide feedback (seektable theory was my guess - as on livetv i had constant progress 00:00 of 00:00 and I can't skip back/forward in such livetv session)

btw: #460 in filename is typo. should be #650...

jpoet commented 2 years ago

Just watching those videos using mpv, the "good" one is clean almost immediately. The "failed" one it takes mpv almost 60 seconds before it plays it clean. It behaves like "keyframes" are very few and far between, but they should not be a whole minute apart. I will have to look at the recorder to see if I can figure out why the recorded file is being affected.

Please provide backend logs with "-v channel,record" when a program on that channel is the only thing recording. I would like to see what it says as it tries to "lock on" to that channel.

jpoet commented 2 years ago

Piotr is this a DVB source? It would be very helpful if you could go into mythtv-setup -> Recording Profiles -> Hardware DVB Encoders -> Default and set "Record Full TS" to yes. Then make a new recording using that profile. The "Full TS" file will not be filtered at all and I can use it do my own testing of that feed and I wont need your logs. Once you have uploaded the "Full TS" file, you can turn that option back off. Thanks

warpme commented 2 years ago

John, Sure i'll capture for you full TS. Do you remember which DB table+field turns-on full TS recording? My BE currently is headless and VNC somehow not works... I have good visual SQL editor so setting on DB level is really easy for me.

jpoet commented 2 years ago

When that option is turned on, an entry is added to the codecparams table: select * from codecparams where name like "%mpts%"; +---------+------------+-------+ | profile | name | value | +---------+------------+-------+ | 17 | recordmpts | 1 |

You would have to backtrack through recordingprofiles and profilegroups to figure out what profie id to use. MariaDB [mythconverg]> select * from profilegroups where name = "Hardware DVB Encoders"; +----+-----------------------+----------+------------+----------+ | id | name | cardtype | is_default | hostname | +----+-----------------------+----------+------------+----------+ | 5 | Hardware DVB Encoders | DVB | 1 | NULL | +----+-----------------------+----------+------------+----------+ 1 row in set (0.000 sec)

MariaDB [mythconverg]> select * from recordingprofiles where profilegroup=5; +----+--------------+------------+------------+--------------+ | id | name | videocodec | audiocodec | profilegroup | +----+--------------+------------+------------+--------------+ | 17 | Default | NULL | NULL | 5 | | 18 | Live TV | NULL | NULL | 5 | | 19 | High Quality | NULL | NULL | 5 | | 20 | Low Quality | NULL | NULL | 5 | +----+--------------+------------+------------+--------------+ 4 rows in set (0.000 sec)

jpoet commented 2 years ago

Piotr, I forgot there are two different methods to get a FULL mpts recording. The one I outlined above probably does not get me what I want to see. It does not seem to be grabbing all the sub-channels, which makes me worry that it is filtering out important bits.

Are you able to do a channel scan? There is an option when scanning channels via mythtv-setup to "Add Full Transport Stream Channels". After the channel scan is done, you will have a "MPTS" version of each transport. If you then record that channel instead of the individual channels, then you get every byte of data in the TS written to the recording file.

ulmus-scott commented 2 years ago

Did this channel work correctly before July 18 (7b2ac1eeb593c0da760cf637a07536f874dce19b)? You had said it also didn't work with reverting the change to BitReader https://github.com/MythTV/mythtv/pull/641 .

warpme commented 2 years ago

Scott, It was working ok before https://github.com/MythTV/mythtv/commit/84a913147c13092ca6b1e39df18f15d064cceb14 (so for sure also before https://github.com/MythTV/mythtv/commit/7b2ac1eeb593c0da760cf637a07536f874dce19b

John, I'm setting up dedicated test backend to gather data for you (decided to do this on dedicated system as on my production backend timeslots where my hommies are not using mythtv is practically only at night or office hours). Hope give you right data soon

warpme commented 2 years ago

John, Pls find full MPTS captured stream: http://warped.inet2.org/fashiontv-full-mpts.ts I'm recording SID=3012:

Video #3
ID                                       : 121 (0x79)
Menu ID                                  : 3012 (0xBC4)
Format                                   : HEVC
Format/Info                              : High Efficiency Video Coding
Format profile                           : Main@L5@Main
Codec ID                                 : 36
Duration                                 : 52 s 80 ms
Width                                    : 3 840 pixels
Height                                   : 2 160 pixels
Display aspect ratio                     : 16:9
Frame rate                               : 25.000 FPS
Standard                                 : Component
Color space                              : YUV
Chroma subsampling                       : 4:2:0
Bit depth                                : 8 bits
Color range                              : Limited
jpoet commented 2 years ago

Thanks Piotr. I am in the process of moving but will try and figure this out soon.

warpme commented 2 years ago

if anything may help you - pls don't hesitate L:-)

ulmus-scott commented 2 years ago

Piotr,

Could you confirm that a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e (parent of 7b2ac1eeb593c0da760cf637a07536f874dce19b ) works? I don't think it does based on my testing with your good sample.

The framerate is not detected correctly (or rather it is, but is then overwritten by vui_parameters()):

master:

2022-10-16 14:56:05.417723 D [1857/2042] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 14:56:05.417729 D [1857/2042] ExternSH HEVCParser.cpp:1917 (parseVPS) - VUI unitsInTick 1 timeScale 25 fixedRate 0
2022-10-16 14:56:05.417739 D [1857/2042] ExternSH H2645Parser.cpp:378 (vui_parameters) - VUI unitsInTick 3186606080 timeScale 1200128000 fixedRate 1
2022-10-16 14:56:05.417762 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379355479μs
2022-10-16 14:56:05.417886 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379381971μs
2022-10-16 14:56:05.417998 D [1857/2042] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65680
2022-10-16 14:56:05.418031 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379408132μs
2022-10-16 14:56:05.418469 D [1857/2042] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 14:56:05.418471 D [1857/2042] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On KeyFrame
2022-10-16 14:56:05.418475 D [1857/2042] ExternSH dtvrecorder.cpp:1016 (FindH2645Keyframes) - DTVRec[8]: Keyframe @ 376 + 562496 = 562872 AU 376
2022-10-16 14:56:05.418512 D [1857/2042] ExternSH portchecker.cpp:75 (checkPort) - PortChecker::checkPort(): host localhost port 3306 timeLimit 30000 linkLocalOnly 1
2022-10-16 14:56:05.419667 D [1857/2042] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 376 + 562496 = 562872 AU 376
2022-10-16 14:56:05.419674 D [1857/2042] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=1 m_frameRate=2997/100 tick_frameRate=2997/100 tick_cnt=2 tick_base=0 _total_dur=33.3667
2022-10-16 14:56:05.420762 I [1857/2042] ExternSH dtvrecorder.cpp:1063 (FindH2645Keyframes) - DTVRec[8]: FindH2645Keyframes: timescale: 1200128000, tick: 3186606080, framerate: 376.616
2022-10-16 14:56:05.421129 I [1857/2042] ExternSH dtvrecorder.cpp:1074 (FindH2645Keyframes) - DTVRec[8]: FindH2645Keyframes: scan type: Progressive
2022-10-16 14:56:05.421271 I [1857/2042] ExternSH dtvrecorder.cpp:1693 (ProcessAVTSPacket) - DTVRec[8]: PID 0x79 Found Payload Start
2022-10-16 14:56:05.421565 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379434293μs
2022-10-16 14:56:05.421657 I [1857/2042] ExternSH dtvrecorder.cpp:1693 (ProcessAVTSPacket) - DTVRec[8]: PID 0x7a Found Payload Start
2022-10-16 14:56:05.427869 D [1857/2042] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65604
2022-10-16 14:56:05.427915 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379460474μs
2022-10-16 14:56:05.428038 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379486635μs
2022-10-16 14:56:05.428087 D [1857/2042] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 14:56:05.428088 D [1857/2042] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 14:56:05.428092 D [1857/2042] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 640892 + 0 = 640892 AU 376
2022-10-16 14:56:05.428101 D [1857/2042] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=2 m_frameRate=1200128000/3186606080 tick_frameRate=1200128000/3186606080 tick_cnt=2 tick_base=33.3667 _total_dur=2688.59
2022-10-16 14:56:05.428191 D [1857/2042] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65716
2022-10-16 14:56:05.428230 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379512816μs
2022-10-16 14:56:05.428265 D [1857/2042] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 14:56:05.428266 D [1857/2042] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 14:56:05.428269 D [1857/2042] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 670784 + 0 = 670784 AU 376
2022-10-16 14:56:05.428275 D [1857/2042] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=3 m_frameRate=1200128000/3186606080 tick_frameRate=1200128000/3186606080 tick_cnt=4 tick_base=33.3667 _total_dur=5343.81
2022-10-16 14:56:05.428386 D [1857/2042] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f7038022b10): PID 121 (0x79) has PCR 12379538977μs
2022-10-16 14:56:05.428409 D [1857/2042] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.

9cacc903e63d2a4573ffa52453627f1e7791a75c broken BitReader (default(?) framerate of 2997/100):

2022-10-16 15:05:48.036101 D [3562/3664] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 15:05:48.036105 W [3562/3664] ExternSH HEVCParser.cpp:1885 (parseVPS) - HEVCParser vps_num_layer_sets_minus1 -1 < 0
2022-10-16 15:05:48.036116 W [3562/3664] ExternSH HEVCParser.cpp:1771 (parseSPS) - HEVCParser num_short_term_ref_pic_sets 4294967295 > 64
2022-10-16 15:05:48.036152 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379355479μs
2022-10-16 15:05:48.036297 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379381971μs
2022-10-16 15:05:48.036428 D [3562/3664] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65680
2022-10-16 15:05:48.036467 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379408132μs
2022-10-16 15:05:48.037032 D [3562/3664] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 15:05:48.037033 D [3562/3664] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On KeyFrame
2022-10-16 15:05:48.037038 D [3562/3664] ExternSH dtvrecorder.cpp:1016 (FindH2645Keyframes) - DTVRec[8]: Keyframe @ 376 + 562496 = 562872 AU 376
2022-10-16 15:05:48.037080 D [3562/3664] ExternSH portchecker.cpp:75 (checkPort) - PortChecker::checkPort(): host localhost port 3306 timeLimit 30000 linkLocalOnly 1
2022-10-16 15:05:48.038549 D [3562/3664] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 376 + 562496 = 562872 AU 376
2022-10-16 15:05:48.038558 D [3562/3664] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=1 m_frameRate=2997/100 tick_frameRate=2997/100 tick_cnt=2 tick_base=0 _total_dur=33.3667
2022-10-16 15:05:48.038560 I [3562/3664] ExternSH dtvrecorder.cpp:1074 (FindH2645Keyframes) - DTVRec[8]: FindH2645Keyframes: scan type: Progressive
2022-10-16 15:05:48.038897 I [3562/3664] ExternSH dtvrecorder.cpp:1693 (ProcessAVTSPacket) - DTVRec[8]: PID 0x79 Found Payload Start
2022-10-16 15:05:48.039181 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379434293μs
2022-10-16 15:05:48.039246 I [3562/3664] ExternSH dtvrecorder.cpp:1693 (ProcessAVTSPacket) - DTVRec[8]: PID 0x7a Found Payload Start
2022-10-16 15:05:48.046232 D [3562/3664] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65604
2022-10-16 15:05:48.046269 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379460474μs
2022-10-16 15:05:48.046368 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379486635μs
2022-10-16 15:05:48.046407 D [3562/3664] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 15:05:48.046408 D [3562/3664] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 15:05:48.046411 D [3562/3664] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 640892 + 0 = 640892 AU 376
2022-10-16 15:05:48.046417 D [3562/3664] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=2 m_frameRate=2997/100 tick_frameRate=2997/100 tick_cnt=4 tick_base=0 _total_dur=66.7334
2022-10-16 15:05:48.046492 D [3562/3664] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65716
2022-10-16 15:05:48.046536 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379512816μs
2022-10-16 15:05:48.046568 D [3562/3664] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 15:05:48.046569 D [3562/3664] ExternSH HEVCParser.cpp:508 (processRBSP) - HEVCParser On Frame
2022-10-16 15:05:48.046572 D [3562/3664] ExternSH dtvrecorder.cpp:1029 (FindH2645Keyframes) - DTVRec[8]: Frame @ 670784 + 0 = 670784 AU 376
2022-10-16 15:05:48.046576 D [3562/3664] ExternSH dtvrecorder.cpp:753 (UpdateFramesWritten) - count=3 m_frameRate=2997/100 tick_frameRate=2997/100 tick_cnt=6 tick_base=0 _total_dur=100.1
2022-10-16 15:05:48.046667 D [3562/3664] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7fb32c0229e0): PID 121 (0x79) has PCR 12379538977μs
2022-10-16 15:05:48.046686 D [3562/3664] ExternSH HEVCParser.cpp:1255 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.

a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e get_bits.h (same as fixed BitReader/master as far as I saw):

2022-10-16 16:23:28.058410 D [47058/47159] ExternSH HEVCParser.cpp:514 (processRBSP) - HEVCParser On Frame
2022-10-16 16:23:28.058418 D [47058/47159] ExternSH HEVCParser.cpp:1917 (parseVPS) - VUI unitsInTick 1 timeScale 25 fixedRate 0
2022-10-16 16:23:28.058429 D [47058/47159] ExternSH H2645Parser.cpp:390 (vui_parameters) - VUI unitsInTick 3186606080 timeScale 1200128000 fixedRate 1
2022-10-16 16:23:28.058446 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379355479μs
2022-10-16 16:23:28.058542 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379381971μs
2022-10-16 16:23:28.058627 D [47058/47159] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65680
2022-10-16 16:23:28.058653 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379408132μs
2022-10-16 16:23:28.059015 D [47058/47159] ExternSH HEVCParser.cpp:1261 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 16:23:28.059016 D [47058/47159] ExternSH HEVCParser.cpp:514 (processRBSP) - HEVCParser On KeyFrame
2022-10-16 16:23:28.059019 D [47058/47159] ExternSH dtvrecorder.cpp:973 (FindH2645Keyframes) - DTVRec[8]: Keyframe @ 376 + 562496 = 562872 AU 376
2022-10-16 16:23:28.059053 D [47058/47159] ExternSH portchecker.cpp:75 (checkPort) - PortChecker::checkPort(): host localhost port 3306 timeLimit 30000 linkLocalOnly 1
2022-10-16 16:23:28.060082 D [47058/47159] ExternSH dtvrecorder.cpp:986 (FindH2645Keyframes) - DTVRec[8]: Frame @ 376 + 562496 = 562872 AU 376
2022-10-16 16:23:28.060090 D [47058/47159] ExternSH dtvrecorder.cpp:710 (UpdateFramesWritten) - count=1 m_frameRate=2997/100 tick_frameRate=2997/100 tick_cnt=2 tick_base=0 _total_dur=33.3667
2022-10-16 16:23:28.061004 I [47058/47159] ExternSH dtvrecorder.cpp:1020 (FindH2645Keyframes) - DTVRec[8]: FindH2645Keyframes: timescale: 1200128000, tick: 3186606080, framerate: 376.616
2022-10-16 16:23:28.061286 I [47058/47159] ExternSH dtvrecorder.cpp:1031 (FindH2645Keyframes) - DTVRec[8]: FindH2645Keyframes: scan type: Progressive
2022-10-16 16:23:28.061402 I [47058/47159] ExternSH dtvrecorder.cpp:1650 (ProcessAVTSPacket) - DTVRec[8]: PID 0x79 Found Payload Start
2022-10-16 16:23:28.061653 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379434293μs
2022-10-16 16:23:28.061716 I [47058/47159] ExternSH dtvrecorder.cpp:1650 (ProcessAVTSPacket) - DTVRec[8]: PID 0x7a Found Payload Start
2022-10-16 16:23:28.068527 D [47058/47159] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65604
2022-10-16 16:23:28.068568 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379460474μs
2022-10-16 16:23:28.068672 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379486635μs
2022-10-16 16:23:28.068717 D [47058/47159] ExternSH HEVCParser.cpp:1261 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 16:23:28.068719 D [47058/47159] ExternSH HEVCParser.cpp:514 (processRBSP) - HEVCParser On Frame
2022-10-16 16:23:28.068722 D [47058/47159] ExternSH dtvrecorder.cpp:986 (FindH2645Keyframes) - DTVRec[8]: Frame @ 640892 + 0 = 640892 AU 376
2022-10-16 16:23:28.068728 D [47058/47159] ExternSH dtvrecorder.cpp:710 (UpdateFramesWritten) - count=2 m_frameRate=1200128000/3186606080 tick_frameRate=1200128000/3186606080 tick_cnt=2 tick_base=33.3667 _total_dur=2688.59
2022-10-16 16:23:28.068805 D [47058/47159] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65716
2022-10-16 16:23:28.068853 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379512816μs
2022-10-16 16:23:28.068886 D [47058/47159] ExternSH HEVCParser.cpp:1261 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 16:23:28.068886 D [47058/47159] ExternSH HEVCParser.cpp:514 (processRBSP) - HEVCParser On Frame
2022-10-16 16:23:28.068889 D [47058/47159] ExternSH dtvrecorder.cpp:986 (FindH2645Keyframes) - DTVRec[8]: Frame @ 670784 + 0 = 670784 AU 376
2022-10-16 16:23:28.068894 D [47058/47159] ExternSH dtvrecorder.cpp:710 (UpdateFramesWritten) - count=3 m_frameRate=1200128000/3186606080 tick_frameRate=1200128000/3186606080 tick_cnt=4 tick_base=33.3667 _total_dur=5343.81
2022-10-16 16:23:28.068990 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379538977μs
2022-10-16 16:23:28.069009 D [47058/47159] ExternSH HEVCParser.cpp:1261 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.
2022-10-16 16:23:28.069010 D [47058/47159] ExternSH HEVCParser.cpp:514 (processRBSP) - HEVCParser On Frame
2022-10-16 16:23:28.069012 D [47058/47159] ExternSH dtvrecorder.cpp:986 (FindH2645Keyframes) - DTVRec[8]: Frame @ 701992 + 0 = 701992 AU 376
2022-10-16 16:23:28.069017 D [47058/47159] ExternSH dtvrecorder.cpp:710 (UpdateFramesWritten) - count=4 m_frameRate=1200128000/3186606080 tick_frameRate=1200128000/3186606080 tick_cnt=6 tick_base=33.3667 _total_dur=7999.03
2022-10-16 16:23:28.078675 D [47058/47159] ExternSH ExternalStreamHandler.cpp:166 (Read) - ExternIO::Read '65536' bytes, buffer size 65640
2022-10-16 16:23:28.078708 D [47058/47159] ExternSH mpegstreamdata.cpp:1040 (ProcessTSPacket) - MPEGStream[8](0x7f45d001efa0): PID 121 (0x79) has PCR 12379565138μs
2022-10-16 16:23:28.078714 D [47058/47159] ExternSH HEVCParser.cpp:1261 (parseSliceSegmentHeader) - HEVCParser PPS Id 0 not valid yet. Skipping parsing of slice.

It looks to me that this channel only (sort of) "worked" with the broken BitReader.

warpme commented 2 years ago

Scott, Indeed - what i recall: -with broken BitReader this channel was working almost ok. Almost as: issue was wrong durations on osd at playback.

This confirms that there is issue with parser at keyframes detection (i think). This is reason - iirc - we merged bit_reader fix and I opened another ticket.

Should i do test with code exactly at https://github.com/MythTV/mythtv/commit/a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e or rather with reverted https://github.com/MythTV/mythtv/commit/a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e ?

btw: probably i done mistake titling this ticket as "regression". from code point of view - this issue is not regression. (it is just functional regression - bit not code regression)

ulmus-scott commented 2 years ago

Piotr,

I checked out a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e to test, so I would say test exactly at a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e . You will need to make distclean and reconfigure due to the intervening FFmpeg 5.1 merge.

warpme commented 2 years ago

Scott, I build exactly https://github.com/MythTV/mythtv/commit/a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e and issue is present 60sec recording has 1h04m duration at playback; livetv osd progress is constantly xx:xx of xx:xx; can't walk back/forward in livetv;

ulmus-scott commented 2 years ago

Since the issue is the same before the switch to BitReader and after fixing BitReader, that rules out the bitstream reader implementation as the source of the issue.

This leaves the parser as the logical source of the problem, since the master and a0f653a2cce0416c1d7d4c1ba22dd1ffb37b315e logs consistently show:

ExternSH HEVCParser.cpp:1917 (parseVPS) - VUI unitsInTick 1 timeScale 25 fixedRate 1
ExternSH H2645Parser.cpp:378 (vui_parameters) - VUI unitsInTick 3186606080 timeScale 1200128000 fixedRate 1

However, if the parser is correct, the source is non-compliant as Rec. ITU-T H.265 v8 (08/2021) § E.3.1VUI parameters semantics says they should be equal: " vui_num_units_in_tick is the number of time units of a clock operating at the frequency vui_time_scale Hz that corresponds to one increment (called a clock tick) of a clock tick counter. vui_num_units_in_tick shall be greater than 0. A clock tick, in units of seconds, is equal to the quotient of vui_num_units_in_tick divided by vui_time_scale. For example, when the picture rate of a video signal is 25 Hz, vui_time_scale may be equal to 27 000 000 and vui_num_units_in_tick may be equal to 1 080 000 and consequently a clock tick may be equal to 0.04 seconds.

When vps_num_units_in_tick is present in the VPS referred to by the SPS, vui_num_units_in_tick, when present, shall be equal to vps_num_units_in_tick, and when not present, is inferred to be equal to vps_num_units_in_tick.

vui_time_scale is the number of time units that pass in one second. For example, a time coordinate system that measures time using a 27 MHz clock has a vui_time_scale of 27 000 000. The value of vui_time_scale shall be greater than 0.

When vps_time_scale is present in the VPS referred to by the SPS, vui_time_scale, when present, shall be equal to vps_time_scale, and when not present, is inferred to be equal to vps_time_scale. "

Rec. ITU-T H.264 (08/2021) § E.2.1VUI parameters semantics does not mention the VPS.

3186606080 / 1200128000 = 2.655221843 s / frame 2.655221843 s / frame ((25 frames / s) 60 s) = 3982.83 seconds = 1 hour 6 minutes 22.83 seconds

The default skip back of 6 seconds only skips back 2.26 frames and 30 seconds for skip forward is only 11.3 frames, so it doesn't really skip back or forwards either in my recordings of your good sample. It does try, but the skip amount is too small.

H2645Parser::vui_parameters() looked correct to me, but I will wait for John's analysis with your full TS sample.

kmdewaal commented 2 years ago

I can confirm that channel FTV UHD on HotBird 13E transponder 8400 has issues, both in master and in fixes/32. Live TV does play correct but it is not possible to skip; when you press the "i" when playing Live TV it should indicate 3 or 4 seconds delay but with FTV UHD the actual time is equal to the end time. I can receive a few more UHD channels but FTV UHD is the only channel that has this problem. When there is a fix for this I can test it.

jpoet commented 2 years ago

On Sat, Oct 29, 2022 at 12:47 PM kmdewaal @.***> wrote:

I can confirm that channel FTV UHD on HotBird 13E transponder 8400 has issues, both in master and in fixes/32. Live TV does play correct but it is not possible to skip; when you press the "i" when playing Live TV it should indicate 3 or 4 seconds delay but with FTV UHD the actual time is equal to the end time. I can receive a few more UHD channels but FTV UHD is the only channel that has this problem. When there is a fix for this I can test it.

Sorry for the delay. I have moved out of my house but my new home is not ready yet. This means I am staying with a friend which means I don't have my normal setup for development and debugging. I will try to rig something up but it may be awhile.

My best guess is that some flag is being miss-interpreted in the HEVC stream which is causing the wrong branch of decoding to happen. Hopefully I can track that down.

John

Message ID: @.***>

ulmus-scott commented 2 years ago

I think the parser is the problem, not the stream. It must get misaligned somewhere.

With the following change, mythffprobe, with any of Piotr's samples as input, says: VUI timing info got 25/1 fps

diff --git a/mythtv/external/FFmpeg/libavcodec/hevc_ps.c b/mythtv/external/FFmpeg/libavcodec/hevc_ps.c
index f665d8053c..5415c016db 100644
--- a/mythtv/external/FFmpeg/libavcodec/hevc_ps.c
+++ b/mythtv/external/FFmpeg/libavcodec/hevc_ps.c
@@ -703,8 +703,8 @@ timing_info:
         }
         vui->vui_num_units_in_tick               = get_bits_long(gb, 32);
         vui->vui_time_scale                      = get_bits_long(gb, 32);
-        if (alt) {
-            av_log(avctx, AV_LOG_INFO, "Retry got %"PRIu32"/%"PRIu32" fps\n",
+        if (1) {
+            av_log(avctx, AV_LOG_INFO, "VUI timing info got %"PRIu32"/%"PRIu32" fps\n",
                    vui->vui_time_scale, vui->vui_num_units_in_tick);
         }
         vui->vui_poc_proportional_to_timing_flag = get_bits1(gb);

No "Retry got" logs without modification.

Looking further at hevc_ps.c, FFmpeg is using the seq_parameter_set_rbsp() definition from §7.3.2.2.1 while we are using the different definition from §F.7.3.2.2.1. I don't know why there are two different definitions of the same structure, but could this be why it becomes misaligned?

ulmus-scott commented 2 years ago

seq_parameter_set_rbsp() is parsed identically to FFmpeg with my two samples (Piotr's FashionTV and John Poet's Smithsonian Channel), i.e. it is parsed as if the code was written to §7.3.2.2.1 instead of §F.7.3.2.2.1 based on the branches taken.

The problem is st_ref_pic_set(stRpsIdx ) is parsed incorrectly, see Rec. ITU-T H.265 v8 (08/2021) §7.3.7 Short-term reference picture set syntax.

The fix https://github.com/MythTV/mythtv/pull/657 :

diff --git a/mythtv/libs/libmythtv/mpeg/HEVCParser.cpp b/mythtv/libs/libmythtv/mpeg/HEVCParser.cpp
index 5a852e56b1..9038fad8ba 100644
--- a/mythtv/libs/libmythtv/mpeg/HEVCParser.cpp
+++ b/mythtv/libs/libmythtv/mpeg/HEVCParser.cpp
@@ -1103,6 +1103,7 @@ static bool shortTermRefPicSet(BitReader& br, int stRPSIdx,

         for (int j = 0; j <= RefRPS->NumDeltaPocs; ++j)
         {
+            used_by_curr_pic_flag[j] = br.get_bits(1); // u(1)
             /*
               use_delta_flag[ j ] equal to 1 specifies that the
               j-th entry in the source candidate short-term RPS
@@ -1113,8 +1114,14 @@ static bool shortTermRefPicSet(BitReader& br, int stRPSIdx,
               short-term RPS. When use_delta_flag[ j ] is not
               present, its value is inferred to be equal to 1.
             */
-            bool val = br.get_bits(1);
-            use_delta_flag[j] = used_by_curr_pic_flag[j] ? val : true;
+            if (!used_by_curr_pic_flag[j])
+            {
+                use_delta_flag[j] = br.get_bits(1); // u(1)
+            }
+            else
+            {
+                use_delta_flag[j] = true;
+            }
         }

With extra logging (do not merge): 0001-HEVCParser-fix-parsing-of-st_ref_pic_set-stRpsIdx-wi.patch.txt

With the extra logging Piotr's sample shows:

HEVCParser.cpp:1786 (parseSPS) - num_short_term_ref_pic_sets = 4
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 0
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 0
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 1
HEVCParser.cpp:1107 (shortTermRefPicSet) - used_by_curr_pic_flag[j] = 0
H2645Parser.cpp:378 (vui_parameters) - VUI unitsInTick 1 timeScale 25 fixedRate 0

while John's Smithsonian Channel sample shows:

HEVCParser.cpp:1786 (parseSPS) - num_short_term_ref_pic_sets = 1
H2645Parser.cpp:378 (vui_parameters) - VUI unitsInTick 166817 timeScale 10000000 fixedRate 0

Further testing would be greatly appreciated since I have no HEVC sources to test.

jpoet commented 2 years ago

Nice work Scott! Thank you for taking this on.