Project

General

Profile

Bug #5722

tsfix: The timediff for AAC-LATM is big

Added by Laurent H. 5 months ago. Updated about 2 months ago.

Status:
New
Priority:
Normal
Assignee:
-
Category:
IPTV
Target version:
-
Start date:
2019-09-01
Due date:
% Done:

0%

Estimated time:
Found in version:
4.3-1804~gebb096804
Affected Versions:

Description

Hello,

I've been having more and more of this errors.
tsfix: The timediff for AAC-LATM is big (675604), using current dts

Then it occurs, kodi client only plays audio.
If i stop and restart the player, then audio/video is ok.

using tvheadend Build: 4.3-1804~gebb096804

see attached log with --trace parser,tsfix,globalheaders


Files

tvheadend.log (896 KB) tvheadend.log Laurent H., 2019-09-01 10:49
tvheadend.log.gz (174 KB) tvheadend.log.gz Laurent H., 2019-09-02 16:42
recording.ts (10.2 MB) recording.ts Laurent H., 2019-09-03 18:46
rstlog_patch.txt (3.87 KB) rstlog_patch.txt Laurent H., 2019-12-08 14:09
rstlog-ok.patch (3.42 KB) rstlog-ok.patch Laurent H., 2019-12-14 13:45

History

#1

Updated by Nabil Alaoui 5 months ago

Any updates on this? I'm having the same errors...

Nabil
sketchgrowl.com (for contact details, I'm a pet portrait artist when I'm not watching TV lol)

note from mpmc: link "removed" due to spam issues.

#2

Updated by kodiaq kodiaq 5 months ago

+1 - Seen with both H264 and H265 streams

#3

Updated by Jaroslav Kysela 5 months ago

Apply the patch bellow and provide new traces, please:

diff --git a/src/plumbing/tsfix.c b/src/plumbing/tsfix.c
index 4b4843e5d..6584597f5 100644
--- a/src/plumbing/tsfix.c
+++ b/src/plumbing/tsfix.c
@@ -552,6 +552,8 @@ tsfix_input_packet(tsfix_t *tf, streaming_message_t *sm)
   tfs = tfs_find(tf, pkt);
   streaming_msg_free(sm);

+  pkt_trace(LS_TSFIX, pkt, "*input*");
+
   if (tfs == NULL || mclk() < tf->tf_start_time) {
     tsfix_packet_drop(tfs, pkt, "start time");
     return;
#4

Updated by Laurent H. 5 months ago

Thank you for your support !

See attached logs after patching

#5

Updated by Jaroslav Kysela 5 months ago

Thanks. It seems that the first I-frame is not passed to tsfix for a reason, so everything gets confused:

Sep  2 16:33:37 nas tvheadend[53654]: parser: deliver (pkt stream 1 HEVC type I pcr 2371666945 dts 2371729945 pts 2371729945 dur 7200 len 59897 err 0 meta 101)
Sep  2 16:33:37 nas tvheadend[53654]: parser: deliver (pkt stream 2 AAC-LATM pcr 2371681345 dts 2371730125 pts 2371730125 dur 2089 len 346 err 0)
Sep  2 16:33:37 nas tvheadend[53654]: tsfix: *input* (pkt stream 2 AAC-LATM pcr 2371681345 dts 2371730125 pts 2371730125 dur 2089 len 346 err 0)
Sep  2 16:33:37 nas tvheadend[53654]: parser: deliver (pkt stream 2 AAC-LATM pcr 2371681345 dts 2371732214 pts 2371732214 dur 2089 len 368 err 0)
Sep  2 16:33:37 nas tvheadend[53654]: tsfix: *input* (pkt stream 2 AAC-LATM pcr 2371681345 dts 2371732214 pts 2371732214 dur 2089 len 368 err 0)
Sep  2 16:33:37 nas tvheadend[53654]: parser: deliver (pkt stream 2 AAC-LATM pcr 2371681345 dts 2371734303 pts 2371734303 dur 2089 len 378 err 0)

Could you also save the MPEG-TS stream (use the URL in the service grid and the pass streaming profile)? Cca 30 seconds. Attach the file to this bug.

#6

Updated by Jaroslav Kysela 5 months ago

I see the problem now. It is in the upper level of code. The first packet is lost, because the stream restart notification is not in sync with the packet delivery, thus the first packets might be lost. We need to queue packets when the streaming restart is asked from the parser code. Give me some time to look into this. I am unfortunately very busy with the "real" work and the personal life.

Hints, if someone other will look into: service_update_elementary_stream() is called, t->s_pending_restart flag is set. From this time, the parser should queue packets before they are delivered - parser_deliver() function - until the streaming is restarted.

#7

Updated by Laurent H. 5 months ago

#8

Updated by Laurent H. 5 months ago

I've tried this, but doesnt seems to work :/

diff --git a/src/parsers/parsers.c b/src/parsers/parsers.c
index a274a094d..a7952ebfa 100644
--- a/src/parsers/parsers.c
+++ b/src/parsers/parsers.c
@@ -125,21 +125,24 @@ parser_deliver(parser_t *t, parser_es_t *st, th_pkt_t *pkt)
   }

 deliver:
+  //ici
diff --git a/src/parsers/parsers.c b/src/parsers/parsers.c
index a274a094d..a7952ebfa 100644
--- a/src/parsers/parsers.c
+++ b/src/parsers/parsers.c
@@ -125,21 +125,24 @@ parser_deliver(parser_t *t, parser_es_t *st, th_pkt_t *pkt)
   }

 deliver:
+  //ici
   pkt->pkt_componentindex = st->es_index;

-  pkt_trace(LS_PARSER, pkt, "deliver");
-
   if (SCT_ISVIDEO(pkt->pkt_type)) {
     pkt->v.pkt_aspect_num = st->es_aspect_num;
     pkt->v.pkt_aspect_den = st->es_aspect_den;
   }

-  /* Forward packet */
-  streaming_target_deliver2(t->prs_output, streaming_msg_create_pkt(pkt));
-
-  /* Decrease our own reference to the packet */
-  pkt_ref_dec(pkt);
-
+  if(!st->es_service->s_pending_restart) {
+    pkt_trace(LS_PARSER, pkt, "deliver");
+    /* Forward packet */
+    streaming_target_deliver2(t->prs_output, streaming_msg_create_pkt(pkt));
+    
+    /* Decrease our own reference to the packet */
+    pkt_ref_dec(pkt);
+  } else {
+    parser_backlog(t, st, pkt);
+  }
 }

 /**
diff --git a/src/parsers/parsers.h b/src/parsers/parsers.h
index f37a56c57..b1d074599 100644
--- a/src/parsers/parsers.h
+++ b/src/parsers/parsers.h
@@ -134,6 +134,8 @@ void parser_enqueue_packet(struct service *t, parser_es_t *st, th_pkt_t *pkt);

 void parser_set_stream_vparam(parser_es_t *st, int width, int height, int duration);

+static void parser_backlog(parser_t *t, parser_es_t *st, th_pkt_t *pkt);
+
 extern const unsigned int mpeg2video_framedurations[16];

 #endif /* PARSERS_H */
#9

Updated by Gary Mann 4 months ago

I'm also having this issue, I'm attempting to stream a VOD video in .mkv format. The logs will look like above but if I keep attempting to view the content I'll eventually be able to stream it from tvheadend. I'm piping the following command when trying to stream the content:

pipe:///usr/bin/ffmpeg -loglevel 0 -re -i http://example.tld/tmp.mkv -c copy -f mpegts pipe:1

#10

Updated by Nabil Madrne 4 months ago

Same issue here. It happens every 5 or 6 attempts to play an IPTV stream.

Jaroslav Kysela wrote:

I see the problem now. It is in the upper level of code. The first packet is lost, because the stream restart notification is not in sync with the packet delivery, thus the first packets might be lost. We need to queue packets when the streaming restart is asked from the parser code. Give me some time to look into this. I am unfortunately very busy with the "real" work and the personal life.

Hints, if someone other will look into: service_update_elementary_stream() is called, t->s_pending_restart flag is set. From this time, the parser should queue packets before they are delivered - parser_deliver() function - until the streaming is restarted.

Jaroslav, could you give me more information about how to solve this ? Not very experienced with this part of the code but I can try. Otherwise, if you find time to fix this, that would be fantastic :)

#11

Updated by Laurent H. about 2 months ago

Hello,

I've tried to had another streaming_message_queue es_rstlog (see attached patch)

Packets are queued to es_rstlog when restart_pending is set.

But the queue is reinitialized when the stream is restarted...

Dec  8 13:58:09 nas tvheadend[48115]: parser: tailq_init rstlog
Dec  8 13:58:09 nas tvheadend[48115]: parser: tailq_init rstlog
Dec  8 13:58:09 nas tvheadend[48115]: parser: vparam 01: w=736 h=576 d=7200 (old w=0 h=0 d=0 meta=0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: deliver to rstlog (pkt stream 1 HEVC type I pcr 1271441547 dts 1271500947 pts 1271500947 dur 7200 len 44646 err 0 meta 100)
Dec  8 13:58:09 nas tvheadend[48115]: parser: vparam 01: w=736 h=576 d=7200 (old w=736 h=576 d=7200 meta=0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: deliver to rstlog (pkt stream 1 HEVC type P pcr 1271441547 dts 1271504547 pts 1271504547 dur 7200 len 6180 err 0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: vparam 01: w=736 h=566 d=7200 (old w=736 h=576 d=7200 meta=0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: deliver to rstlog (pkt stream 1 HEVC type P pcr 1271448747 dts 1271508147 pts 1271508147 dur 7200 len 7954 err 0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: tailq_init rstlog
Dec  8 13:58:09 nas tvheadend[48115]: parser: tailq_init rstlog
Dec  8 13:58:09 nas tvheadend[48115]: parser: pcr drop (pkt stream 0 AAC-LATM pcr <unset> dts 1271502633 pts 1271502633 dur 2089 len 359 err 0)
Dec  8 13:58:09 nas tvheadend[48115]: parser: deliver (pkt stream 2 AAC-LATM pcr <unset> dts <unset> pts <unset> dur 0 len 0 err 1)
Dec  8 13:58:09 nas tvheadend[48115]: tsfix: *input* (pkt stream 2 AAC-LATM pcr <unset> dts <unset> pts <unset> dur 0 len 0 err 1)
#12

Updated by Laurent H. about 2 months ago

Hi,

I moved the queue to parser struct, see attached rstlog-ok.patch

Seems to works for me in most cases, but i'm not sure if function parser_create is the best place to send pkt from rstlog.

Can someone test and review this patch ?

Thank you.

Also available in: Atom PDF