DTS issues question #50

peyoh · 2015-11-19T08:06:26Z

Hello,
sometimes, when the input stream is broken for some reason, packager fails in
DCHECK_GT(media_sample->dts(), pending_sample_->dts());

[1119/095331:FATAL:es_parser_h264.cc(318)] Check failed: media_sample->dts() > pending_sample_->dts() (17179995184 vs. 17185193584)
#0 0x0000006ecb8e base::debug::StackTrace::StackTrace()
#1 0x000000682072 logging::LogMessage::~LogMessage()
#2 0x0000009e6c62 edash_packager::media::mp2t::EsParserH264::EmitFrame()
#3 0x0000009e5dc1 edash_packager::media::mp2t::EsParserH264::ParseInternal()
#4 0x0000009e52af edash_packager::media::mp2t::EsParserH264::Parse()
#5 0x0000009dd4f6 edash_packager::media::mp2t::TsSectionPes::ParseInternal()
#6 0x0000009db4a3 edash_packager::media::mp2t::TsSectionPes::Emit()
#7 0x0000009db27e edash_packager::media::mp2t::TsSectionPes::Parse()
#8 0x0000009ccc6c edash_packager::media::mp2t::PidState::PushTsPacket()
#9 0x0000009ce226 edash_packager::media::mp2t::Mp2tMediaParser::Parse()
#10 0x00000063ef40 edash_packager::media::Demuxer::Parse()
#11 0x00000063f270 edash_packager::media::Demuxer::Run()
#12 0x000000410944 edash_packager::media::RemuxJob::Run()
#13 0x0000006c4201 base::SimpleThread::ThreadMain()
#14 0x0000006c361a base::(anonymous namespace)::ThreadFunc()
#15 0x7fb849924df5 start_thread
#16 0x7fb8496521ad __clone

In fact this could not be happened with a well created video file, but it is possible with a live stream.
May you suggest some workaround on this?

The text was updated successfully, but these errors were encountered:

kqyang · 2015-11-19T19:20:23Z

It is difficult to handle it properly without knowing why the dts is decreasing. I suggest looking into the root cause - a difference of 17179995184 vs. 17185193584 is significant.

One possible workaround might be to add a fictional offset to adjust the timestamp when seeing a big gap in dts, something like

src/packager/media/formats/mp2t/es_parser_h264.cc&l=317

media_sample->set_dts(current_timing_desc.dts + timestamp_adjustment_);
media_sample->set_pts(current_timing_desc.pts + timestamp_adjustment_);
if(media_sample->dts() < pending_sample_->dts()) {
int64_t gap = pending_sample_->dts() - media_sample->dts();
timestamp_adjustment_ += gap + kEstimatedFrameDuration;
media_sample->set_dts(current_timing_desc.dts + timestamp_adjustment_);
media_sample->set_pts(current_timing_desc.pts + timestamp_adjustment_);
}

That said, I think the best option is still to find the root cause and solve the problem there. The workaround should be avoided if possible.

peyoh · 2015-11-20T08:53:03Z

Yes,
the reason is clear.
The stream is received by DVB-S2 receiver from the satellite. Next is re-streamed to a edash_packager. But sometimes because some transport/encoding errors DTS is decreasing. Why? Who knows. The signal comes from the satellite.
Thank you for the idea.

BRS/
Peyo

kqyang · 2016-04-18T21:14:38Z

@peyoh I have updated https://github.com/kqyang/edash-packager to ignore samples with decreasing timestamp. Can you give it a try? It will be great if you can post logging messages as well. I am interested in seeing what is the timestamp pattern when it happens. Thanks.

peyoh · 2016-04-20T11:58:52Z

got it.

peyoh · 2016-04-22T05:24:23Z

Hi,
with this branch I see some unseen before logs. :)

[0420/122707:INFO:demuxer.cc(60)] Initialize Demuxer for file 'udp://239.204.0.14:7000'.
[0420/122707:ERROR:container_names.cc(1032)] Failure while processing: ReadBits(&reader, 11) == 0x7ff
[0420/122707:ERROR:container_names.cc(1109)] Failure while processing: ValidMpegAudioFrameHeader( buffer + offset, buffer_size - offset, &framesize)
[0420/122707:ERROR:container_names.cc(710)] Failure while processing: ReadBits(&reader, 24) == 1

and

[0421/043107:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/043107:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/043107:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/043107:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/043107:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/043107:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/043107:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/043107:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.

kqyang · 2016-04-22T18:36:13Z

You can ignore the errors in container_names.cc - these errors should have been suppressed, sorry for the confusion.

As for the warnings in nalu_reader.cc, it is as a result of #93 fix - the source content is not properly escaped.

Other than that, is it still running? Have you seen errors like "Seeing sample with dts ..."?

peyoh · 2016-04-23T14:22:01Z

Hi KQ,
that's the latest log before exit.

[0421/215952:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/215952:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/220146:WARNING:mpd_builder.cc(1259)] Found a gap of size 119040 > kRoundingErrorGrace (5). The new segment starts at 17704734840 but the previous segment ends at 17704615800.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xbf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xbf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xdf).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(55)] Unspecified or reserved nal_unit_type 31 (header 0x7f).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/230525:WARNING:nalu_reader.cc(55)] Unspecified or reserved nal_unit_type 31 (header 0x7f).
[0421/230525:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0421/235140:WARNING:mpd_builder.cc(1259)] Found a gap of size 13440 > kRoundingErrorGrace (5). The new segment starts at 18298164600 but the previous segment ends at 18298151160.
[0422/001058:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xff).
[0422/001058:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0422/001058:WARNING:nalu_reader.cc(41)] forbidden_zero_bit shall be equal to 0 (header 0xff).
[0422/001058:WARNING:nalu_reader.cc(311)] Seeing invalid NAL unit. Emulation prevention may not have been applied properly. Assuming it is part of the previous NAL unit.
[0422/005443:WARNING:mpd_builder.cc(1259)] Found a gap of size 26880 > kRoundingErrorGrace (5). The new segment starts at 18638572920 but the previous segment ends at 18638546040.
[0422/094940:WARNING:mpd_builder.cc(1259)] Found a gap of size 15360 > kRoundingErrorGrace (5). The new segment starts at 21527328120 but the previous segment ends at 21527312760.
[0422/115901:WARNING:mpd_builder.cc(1259)] Found a gap of size 3545562936 > kRoundingErrorGrace (5). The new segment starts at 25770763056 but the previous segment ends at 22225200120.
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:INFO:multi_segment_segmenter.cc(37)] MultiSegmentSegmenter outputs init segment: /storage/web/dash/501/edash-video-288.mp4
[0422/120435:INFO:multi_segment_segmenter.cc(43)] MultiSegmentSegmenter does not have index range.
[0422/120435:INFO:multi_segment_segmenter.cc(37)] MultiSegmentSegmenter outputs init segment: /storage/web/dash/501/edash-video-576.mp4
[0422/120435:INFO:multi_segment_segmenter.cc(43)] MultiSegmentSegmenter does not have index range.
[0422/120435:INFO:mp4_muxer.cc(170)] MP4 file '/storage/web/dash/501/edash-video-288.mp4' finalized.
[0422/120435:INFO:mp4_muxer.cc(170)] MP4 file '/storage/web/dash/501/edash-video-576.mp4' finalized.
[0422/120435:INFO:multi_segment_segmenter.cc(37)] MultiSegmentSegmenter outputs init segment: /storage/web/dash/501/edash-video-512.mp4
[0422/120435:INFO:multi_segment_segmenter.cc(43)] MultiSegmentSegmenter does not have index range.
[0422/120435:INFO:multi_segment_segmenter.cc(37)] MultiSegmentSegmenter outputs init segment: /storage/web/dash/501/edash-video-384.mp4
[0422/120435:INFO:multi_segment_segmenter.cc(43)] MultiSegmentSegmenter does not have index range.
[0422/120435:INFO:mp4_muxer.cc(170)] MP4 file '/storage/web/dash/501/edash-video-512.mp4' finalized.
[0422/120435:INFO:multi_segment_segmenter.cc(37)] MultiSegmentSegmenter outputs init segment: /storage/web/dash/501/edash-audio.mp4
[0422/120435:INFO:multi_segment_segmenter.cc(43)] MultiSegmentSegmenter does not have index range.
[0422/120435:INFO:mp4_muxer.cc(170)] MP4 file '/storage/web/dash/501/edash-video-384.mp4' finalized.
[0422/120435:INFO:mp4_muxer.cc(170)] MP4 file '/storage/web/dash/501/edash-audio.mp4' finalized.

peyoh · 2016-04-26T06:52:22Z

Hi KQ,

here are additional logs:

[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598842672 <= pending sample dts 8598846272. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598840992 <= pending sample dts 8598844592. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598840992 <= pending sample dts 8598844592. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598846272 <= pending sample dts 8598846272. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598844592 <= pending sample dts 8598844592. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598844592 <= pending sample dts 8598844592. Sample ignored.
[0426/095141:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 8598844592 <= pending sample dts 8598844592. Sample ignored.

kqyang · 2016-04-26T17:25:40Z

The error in your previous log looks like a network failure:

[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11
[0422/120435:WARNING:udp_file_posix.cc(112)] UdpFile::Read result -1 11

From your 2nd log, the code was able to skip some misbehaved samples. Do you see any playback problem?

peyoh · 2016-04-27T08:53:20Z

Hi,

[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2678400 <= pending sample dts 106459200. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2682240 <= pending sample dts 106463040. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2682000 <= pending sample dts 106459200. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2685840 <= pending sample dts 106463040. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2682000 <= pending sample dts 106459200. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2685600 <= pending sample dts 106459200. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2682000 <= pending sample dts 106459200. Sample ignored.
[0427/110833:WARNING:es_parser_h264.cc(342)] Seeing sample with dts 2685600 <= pending sample dts 106459200. Sample ignored.

With this time difference, I must wait a lot of time before see something.
Seems this is not the right solution.

kqyang · 2016-04-27T17:22:05Z

Em... It is about 20 minutes difference.

What do you expect to see? A continuous playback from sample at 106459200 to sample at 2678400, i.e. treat the sample at 2678400 as the next sample of the sample at 106459200?

kqyang · 2016-04-27T17:34:10Z

Another question:

How does the timestamp progress? Something like (1) or (2)?

(1) A sequence of samples with incorrect timestamp (T-1000 to T-800) are inserted between T+50 and T+51:

T, T+1, T+2, ... T+50, T-1000, T-999, T-998, ... T-801, T-800, T+51, T+52, T+53

(2) T-1000 is the next sample of T+50 (The system adjusts timestamp by 1050):

T, T+1, T+2, ... T+50, T-1000, T-999, T-998, ... T-801, T-800, ...

It will be helpful if you can post the full log.

peyoh · 2016-04-28T10:39:03Z

501.log.gz

Hi KQ,
attached file is the log. Not the same as in the previous post, but it's similar.

kqyang · 2016-04-29T18:36:12Z

Ok, so it looks like it is more like case 2 mentioned above. Another solution I have in mind now is to start a new segment when seeing timestamp rolling back. Timeline will be something like:

          <SegmentTimeline>
            <S t="29865840" d="270000" r="4"/>
            <S t="313440" d="270000" r="130"/>
          </SegmentTimeline>

It will then be up to player to decide how to handle a timeline like this.

peyoh · 2016-05-02T12:56:43Z

Hi KQ,
can you please explain to me what this line means:

<S t="29865840" d="270000" r="4"/>

Because I'm unable to fully understand it from the spec. I know, that this is not a support forum, but this can help me to implement it properly at the client side.
Peyo

kqyang · 2016-05-02T17:33:08Z

See ISO/IEC 23009-1:2014 5.3.9.6.2 for the semantics of segment timeline. Basically 't' specifies the start time of the segment, and 'd' specifies the duration of the segment, and 'r' specifies the repeat count,

<S t="29865840" d="270000" r="4"/>

is equivalent to

<S t="29865840" d="270000"/>
<S t="30135840" d="270000" r="3"/>

peyoh · 2016-08-01T10:36:24Z

Hi KQ.
I see, that in the standard the only proper solution of this case is to create a new period as you mentioned in #89 . I cannot see any other solution.
The PTS/DTS size is 33 bits, so the maximum continuous incrementing seconds count stored in it is no more than 95443 or a little more than a day. In this case the current SDK without multiple periods support isn't able to play live stream properly more than 95443 seconds. Am I right?

kqyang · 2016-08-01T20:06:26Z

The PTS/DTS size is 33 bits, so the maximum continuous incrementing seconds count stored in it is no more than 95443 or a little more than a day. In this case the current SDK without multiple periods support isn't able to play live stream properly more than 95443 seconds. Am I right?

No, that is not the cause of the problem. Although PTS/DTS is only 33 bits, it should wrap around and restart from 0. Our code handles that internally. We keep an internal base, the actual time stamp is calculated as (base << 33) + pts/dts. Whenever the time stamp wraps around, the internal base is increment by one.

peyoh · 2016-08-05T13:07:17Z

You do that something before fragmenter? Can you show me where?

kqyang · 2016-08-11T22:07:49Z

Sorry for the late reply. Somehow missed your message.

Here is the code to unroll the timestamp:

https://github.com/google/shaka-packager/blob/4f9c8ea7817b397c4f2dd83311f528200650bd3d/packager/media/formats/mp2t/ts_section_pes.cc#L22

kqyang · 2017-09-28T21:52:55Z

Closing due to long time of no activity. Feel free to re-open if there is any update.

kqyang added the type: question A question from the community label Nov 19, 2015

peyoh closed this as completed Nov 20, 2015

kqyang reopened this Apr 11, 2016

kqyang mentioned this issue Apr 11, 2016

Re-read old manifest after crash #89

Open

peyoh closed this as completed Apr 27, 2016

peyoh reopened this Apr 27, 2016

kqyang closed this as completed Sep 28, 2017

shaka-bot added the status: archived Archived and locked; will not be updated label Apr 19, 2018

shaka-project locked and limited conversation to collaborators Apr 19, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

DTS issues question #50

DTS issues question #50

peyoh commented Nov 19, 2015

kqyang commented Nov 19, 2015

peyoh commented Nov 20, 2015

kqyang commented Apr 18, 2016

peyoh commented Apr 20, 2016

peyoh commented Apr 22, 2016

kqyang commented Apr 22, 2016

peyoh commented Apr 23, 2016

peyoh commented Apr 26, 2016

kqyang commented Apr 26, 2016

peyoh commented Apr 27, 2016

kqyang commented Apr 27, 2016

kqyang commented Apr 27, 2016

peyoh commented Apr 28, 2016 •

edited

Loading

kqyang commented Apr 29, 2016

peyoh commented May 2, 2016

kqyang commented May 2, 2016

peyoh commented Aug 1, 2016

kqyang commented Aug 1, 2016

peyoh commented Aug 5, 2016

kqyang commented Aug 11, 2016

kqyang commented Sep 28, 2017

DTS issues question #50

DTS issues question #50

Comments

peyoh commented Nov 19, 2015

kqyang commented Nov 19, 2015

peyoh commented Nov 20, 2015

kqyang commented Apr 18, 2016

peyoh commented Apr 20, 2016

peyoh commented Apr 22, 2016

kqyang commented Apr 22, 2016

peyoh commented Apr 23, 2016

peyoh commented Apr 26, 2016

kqyang commented Apr 26, 2016

peyoh commented Apr 27, 2016

kqyang commented Apr 27, 2016

kqyang commented Apr 27, 2016

peyoh commented Apr 28, 2016 • edited Loading

kqyang commented Apr 29, 2016

peyoh commented May 2, 2016

kqyang commented May 2, 2016

peyoh commented Aug 1, 2016

kqyang commented Aug 1, 2016

peyoh commented Aug 5, 2016

kqyang commented Aug 11, 2016

kqyang commented Sep 28, 2017

peyoh commented Apr 28, 2016 •

edited

Loading