diff mbox

[INVITATION] help debugging cAudioRepacker

Message ID 431A04AD.4090901@gmx.de
State New
Headers

Commit Message

Reinhard Nissl Sept. 3, 2005, 8:16 p.m. UTC 
  Hi,

Reinhard Nissl wrote:

> as some people seem to get messages like the following several seconds 
> (> 60) after switching to a certain channel (or after a recording has 
> switched a device)
> 
> Sep  2 11:12:49 video vdr[14940]: cAudioRepacker: skipped 911 bytes to 
> sync on next audio frame
> Sep  2 11:12:49 video vdr[14940]: cAudioRepacker: skipped 785 bytes to 
> sync on next audio frame
> Sep  2 11:12:50 video vdr[14940]: cAudioRepacker: skipped 221 bytes to 
> sync on next audio frame
> 
> it may be likely that there is a bug in cAudioRepacker. Therefore I've 
> added some debug output to possibly identify a bug.
> 
> The attached patch is against vanilla VDR-1.3.31 and contains all my 
> previously released patches since VDR-1.3.31 plus the new debug messages.

I've updated the patch. It stores now up to 100 TS packets, that led to 
a wrong audio header respectively to synchronisation. The files are 
written to /video, as I assume some space at this location ;-) If you 
want to use a different location, just have a look into cTSLogger::Dump().

While adding the dumper to cAudioRepacker, I've discovered a little bug 
which could lead to recognizing an audio frame header too early: after a 
frame is done, at least 4 bytes (which are counted by variable 
skippedBytes) need to be read before scanner can be tested for a valid 
audio header.

> As I experience such messages only rarely it takes quite some time to 
> wait for the next log message and there are only about 30 hours left 
> before VDR-1.3.32 is likely to be released.
> 
> So I really invite you to help debugging this issue. Please send any 
> such messages to the list or maybe to me privately. But be aware: I'm 
> not interested in the messages that happen immediately after tuning the 
> device! Especially VDR-1.3.31 reports sometimes a lot of them, as 
> waiting for the tuner getting locked was removed. There is nothing 
> special about these messages.
> 
> To make it clear once more: just send such messages that happen for 
> example 60 seconds after the last tuning activity (log message: 
> "switching to channel X" or "switching device X to channel Y").
> 
> The sent log messages should also include the lines which allow to 
> identy the thread that drives cAudioRepacker. Typically these log 
> messages (like "transfer thread started" or "recording thread started") 
> follow the switching messages.

Please include the dumped TS logfiles (/video/ts_*.log) too.

> NPTL users: please turn off NPTL for this test (by defining an 
> environment variable: export LD_ASSUME_KERNEL=2.4.1) as it is not 
> possible to indentify the reporting thread otherwise.

Bye.

Comments

Reinhard Nissl Sept. 6, 2005, 9:56 p.m. UTC | #1 
Hi,

Reinhard Nissl wrote:

>> as some people seem to get messages like the following several seconds 
>> (> 60) after switching to a certain channel (or after a recording has 
>> switched a device)
>>
>> Sep  2 11:12:49 video vdr[14940]: cAudioRepacker: skipped 911 bytes to 
>> sync on next audio frame
>> Sep  2 11:12:49 video vdr[14940]: cAudioRepacker: skipped 785 bytes to 
>> sync on next audio frame
>> Sep  2 11:12:50 video vdr[14940]: cAudioRepacker: skipped 221 bytes to 
>> sync on next audio frame
>>
>> it may be likely that there is a bug in cAudioRepacker. Therefore I've 
>> added some debug output to possibly identify a bug.
>>
>> The attached patch is against vanilla VDR-1.3.31 and contains all my 
>> previously released patches since VDR-1.3.31 plus the new debug messages.
> 
> I've updated the patch. It stores now up to 100 TS packets, that led to 
> a wrong audio header respectively to synchronisation. The files are 
> written to /video, as I assume some space at this location ;-) If you 
> want to use a different location, just have a look into cTSLogger::Dump().
> 
> While adding the dumper to cAudioRepacker, I've discovered a little bug 
> which could lead to recognizing an audio frame header too early: after a 
> frame is done, at least 4 bytes (which are counted by variable 
> skippedBytes) need to be read before scanner can be tested for a valid 
> audio header.
> 
>> As I experience such messages only rarely it takes quite some time to 
>> wait for the next log message and there are only about 30 hours left 
>> before VDR-1.3.32 is likely to be released.
>>
>> So I really invite you to help debugging this issue. Please send any 
>> such messages to the list or maybe to me privately. But be aware: I'm 
>> not interested in the messages that happen immediately after tuning 
>> the device! Especially VDR-1.3.31 reports sometimes a lot of them, as 
>> waiting for the tuner getting locked was removed. There is nothing 
>> special about these messages.
>>
>> To make it clear once more: just send such messages that happen for 
>> example 60 seconds after the last tuning activity (log message: 
>> "switching to channel X" or "switching device X to channel Y").
>>
>> The sent log messages should also include the lines which allow to 
>> identy the thread that drives cAudioRepacker. Typically these log 
>> messages (like "transfer thread started" or "recording thread 
>> started") follow the switching messages.
> 
> Please include the dumped TS logfiles (/video/ts_*.log) too.
> 
>> NPTL users: please turn off NPTL for this test (by defining an 
>> environment variable: export LD_ASSUME_KERNEL=2.4.1) as it is not 
>> possible to indentify the reporting thread otherwise.

Meanwhile I've got a second report. Dumping it like that

od -Ax -w188 -v -t x1 ts_22252_2342936_0xC0_005_36676_100.log | less -S

shows a discontinuity at the end of the file

                  v
004218 47 00 88 14 d0 a3 e1 59 3a 12 74 0e 49 ca 80 c2 5d 57 58 50 74 ed 
4d 2c 5a f5 46 b5 6d a3 16 b5 4a 52 88 46 b5 ad 84 08 4a da 91 9d a5 57 
cd cf 9b 9b 2e e6 ed 67 1c 87 27
0042d4 47 00 88 18 b6 b3 63 c3 24 32 22 48 92 d8 b6 31 58 a4 24 20 13 11 
eb 38 ae aa 6b 2a e7 3d ef 79 e0 c4 a5 2a 75 18 99 eb 10 e2 c6 d9 59 96 
9a 79 a7 96 b5 fe 47 91 e3 51 a9
                  ^

In such a case, cAudioRepacker can do nothing else than synchronize to 
the next audio frame header and drop any data up to synchronization. 
This is the same as what the decoder did before VDR-1.3.31, except 
reporting that it has happened.

Missing TS packets are a matter of digital broadcasting and cannot be 
avoided completely, but optimizing the reception system my minimize them.

If you still find issues with cAudioRepacker that are not related to 
missing TS packets (use the above command and check the tail), feel free 
to report them further. Many thanks to all of you, who supported me by 
sending reports or by just running the modified cAudioRepacker with no 
unusual behaviour ;-)

BTW: attached you'll find the file remux.c of the upcoming VDR-1.3.32, 
which is almost identical to the version contained in last patch, but 
with all debug messages removed again.

Bye.
diff mbox

Patch

--- ../vdr-1.3.31-orig/remux.c	2005-08-28 13:46:44.000000000 +0200
+++ remux.c	2005-09-03 21:39:29.000000000 +0200
@@ -104,6 +104,7 @@  public:
   virtual int QuerySnoopSize(void) { return 0; }
   void SetMaxPacketSize(int MaxPacketSize) { maxPacketSize = MaxPacketSize; }
   void SetSubStreamId(uint8_t SubStreamId) { subStreamId = SubStreamId; }
+  virtual void LogTSPacket(const uchar *Data) {}
   };
 
 int cRepacker::Put(cRingBufferLinear *ResultBuffer, const uchar *Data, int Count, int CapacityNeeded)
@@ -142,7 +143,7 @@  void cCommonRepacker::Reset(void)
 {
   cRepacker::Reset();
   skippedBytes = 0;
-  packetTodo = maxPacketSize - 6 - 3;
+  packetTodo = 0;
   fragmentLen = 0;
   pesHeaderLen = 0;
   pesHeaderBackupLen = 0;
@@ -361,7 +362,7 @@  void cVideoRepacker::Repack(cRingBufferL
         done++;
         todo--;
         // do we have to start a new packet as there is no more space left?
-        if (--packetTodo <= 0) {
+        if (state != syncing && --packetTodo <= 0) {
            // we connot start a new packet here if the current might end in a start
            // code and this start code shall possibly be put in the next packet. So
            // overfill the current packet until we can safely detect that we won't
@@ -468,6 +469,9 @@  void cVideoRepacker::Repack(cRingBufferL
 
 int cVideoRepacker::BreakAt(const uchar *Data, int Count)
 {
+  if (initiallySyncing)
+     return -1; // fill the packet buffer completely until we have synced once
+
   int PesPayloadOffset = 0;
 
   if (AnalyzePesHeader(Data, Count, PesPayloadOffset) <= phInvalid)
@@ -502,6 +506,60 @@  int cVideoRepacker::BreakAt(const uchar 
   return PesPayloadOffset + packetTodo + 4;
 }
 
+// --- cTSLogger -------------------------------------------------------------
+
+class cTSLogger
+{
+  uchar *buffer;
+  int size;
+  int fill;
+  int64_t count; 
+  int dumps;
+  int cid;
+ 
+public:
+  cTSLogger(int Cid);
+  ~cTSLogger();
+  void Put(const uchar *Data);
+  void Dump();
+};
+
+cTSLogger::cTSLogger(int Cid)
+{
+  size = 100; // number of TS packets to log
+  buffer = new uchar[size * 188];
+  fill = 0;
+  count = 0;
+  dumps = 0;
+  cid = Cid;
+}
+
+cTSLogger::~cTSLogger()
+{
+  delete [] buffer;
+}
+
+void cTSLogger::Put(const uchar *Data)
+{
+  memcpy(&buffer[(count++ % size) * 188], Data, 188);
+  if (fill < size)
+     fill++;
+}
+
+void cTSLogger::Dump()
+{
+  char name[200];
+  sprintf(name, "/video/ts_%d_%ld_0x%02X_%03d_%lld_%d.log", getpid(), pthread_self(), cid, dumps++, count, fill);
+  esyslog("cTSLogger: dumping to file '%s'", name);
+
+  FILE *f = fopen(name, "wb");
+  for (int64_t n = count - fill; n < count; n++)
+      fwrite(&buffer[(n % size) * 188], 188, 1, f);
+  fclose(f);
+
+  fill = 0;
+}
+
 // --- cAudioRepacker --------------------------------------------------------
 
 class cAudioRepacker : public cCommonRepacker {
@@ -513,9 +571,12 @@  private:
     } state;
   int frameTodo;
   int frameSize;
-  static bool IsValidAudioHeader(uint32_t Header, bool Mpeg2, int *FrameSize = NULL);
+  int cid;
+  /* static */ bool IsValidAudioHeader(uint32_t Header, bool Mpeg2, int *FrameSize = NULL);
+  cTSLogger tsLogger;
+  virtual void LogTSPacket(const uchar *Data) { tsLogger.Put(Data); }
 public:
-  cAudioRepacker(void);
+  cAudioRepacker(int Cid);
   virtual void Reset(void);
   virtual void Repack(cRingBufferLinear *ResultBuffer, const uchar *Data, int Count);
   virtual int BreakAt(const uchar *Data, int Count);
@@ -536,8 +597,10 @@  int cAudioRepacker::bitRates[2][3][16] =
   0,   8,  16,  24,  32,  40,  48,  56,  64,  80,  96, 112, 128, 144, 160, -1
   };
 
-cAudioRepacker::cAudioRepacker(void)
+cAudioRepacker::cAudioRepacker(int Cid)
+  : tsLogger(Cid)
 {
+  cid = Cid;
   Reset();
 }
 
@@ -566,23 +629,41 @@  bool cAudioRepacker::IsValidAudioHeader(
 //int orignal_copy       = (Header & 0x00000004) >>  2;
   int emphasis           = (Header & 0x00000003);
 
-  if (syncword != 0xFFF)
+  if (syncword != 0xFFF) {
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: syncword", cid, Header);
      return false;
+     }
 
-  if (id == 0 && !Mpeg2) // reserved in MPEG 1
+  if (id == 0 && !Mpeg2) { // reserved in MPEG 1
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: id", cid, Header);
      return false;
+     }
 
-  if (layer == 0) // reserved
+  if (layer == 0) { // reserved
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: layer", cid, Header);
      return false;
+     }
 
-  if (bitrate_index == 0xF) // forbidden
+  if (bitrate_index == 0xF) { // forbidden
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: bitrate_index", cid, Header);
      return false;
+     }
 
-  if (sampling_frequency == 3) // reserved
+  if (sampling_frequency == 3) { // reserved
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: sampling_frequency", cid, Header);
      return false;
+     }
 
-  if (emphasis == 2) // reserved
+  if (emphasis == 2) { // reserved
+     if (FrameSize)
+        esyslog("cAudioRepacker(0x%02X): invalid audio header 0x%08X: emphasis", cid, Header);
      return false;
+     }
 
   if (FrameSize) {
      if (bitrate_index == 0)
@@ -649,12 +730,9 @@  void cAudioRepacker::Repack(cRingBufferL
   const uchar *payload = data;
 
   while (todo > 0) {
-        // collect number of skipped bytes while syncing
-        if (state <= syncing)
-           skippedBytes++;
-        else if (frameTodo > 0) {
-           frameTodo--;
-           if (frameTodo == 0 && state == scanFrame) {
+        // do we have to start a new packet as the current is done?
+        if (frameTodo > 0) {
+           if (--frameTodo == 0) {
               // the current audio frame is is done now. So push out the packet to
               // start a new packet for the next audio frame.
               PushOutPacket(ResultBuffer, payload, data - payload);
@@ -662,11 +740,15 @@  void cAudioRepacker::Repack(cRingBufferL
               state = syncing;
               }
            }
+        // collect number of skipped bytes while syncing
+        if (state <= syncing)
+           skippedBytes++;
         // did we reach an audio frame header?
         scanner <<= 8;
         scanner |= *data;
         if ((scanner & 0xFFF00000) == 0xFFF00000) {
-           if (frameTodo <= 0 && IsValidAudioHeader(scanner, mpegLevel == phMPEG2, &frameSize)) {
+           int LastFrameSize = frameSize;
+           if (frameTodo <= 0 && (frameSize == 0 || skippedBytes >= 4) && IsValidAudioHeader(scanner, mpegLevel == phMPEG2, &frameSize)) {
               if (state == scanFrame) {
                  // As a new audio frame starts here, the previous one is done. So push
                  // out the packet to start a new packet for the next audio frame. If
@@ -678,10 +760,16 @@  void cAudioRepacker::Repack(cRingBufferL
                  state = syncing;
                  }
               if (state == syncing) {
+                 // report a change of frame size
+                 if (!initiallySyncing && LastFrameSize != frameSize)
+                    esyslog("cAudioRepacker(0x%02X): frame size changes from %d to %d", cid, LastFrameSize, frameSize);
                  if (initiallySyncing) // omit report for the typical initial case
                     initiallySyncing = false;
-                 else if (skippedBytes > SkippedBytesLimit) // report that syncing dropped some bytes
-                    esyslog("cAudioRepacker: skipped %d bytes to sync on next audio frame", skippedBytes - SkippedBytesLimit);
+                 else if (skippedBytes > SkippedBytesLimit) { // report that syncing dropped some bytes
+                    esyslog("cAudioRepacker(0x%02X): skipped %d bytes to sync on next audio frame", cid, skippedBytes - SkippedBytesLimit);
+                    esyslog("cAudioRepacker(0x%02X): synchronization based on this header: 0x%08X, frame size: %d", cid, scanner, frameSize);
+                    tsLogger.Dump();
+                    }
                  skippedBytes = 0;
                  // if there is a PES header available, then use it ...
                  if (pesHeaderBackupLen > 0) {
@@ -728,11 +816,15 @@  void cAudioRepacker::Repack(cRingBufferL
                  }
               }
            }
+        else if (skippedBytes == SkippedBytesLimit) {
+           esyslog("cAudioRepacker(0x%02X): no valid audio frame header (0x%08X) at expected location", cid, scanner);
+           tsLogger.Dump();
+           }
         data++;
         done++;
         todo--;
         // do we have to start a new packet as there is no more space left?
-        if (--packetTodo <= 0) {
+        if (state != syncing && --packetTodo <= 0) {
            // We connot start a new packet here if the current might end in an audio
            // frame header and this header shall possibly be put in the next packet. So
            // overfill the current packet until we can safely detect that we won't
@@ -829,13 +921,16 @@  void cAudioRepacker::Repack(cRingBufferL
   // report that syncing dropped some bytes
   if (skippedBytes > SkippedBytesLimit) {
      if (!initiallySyncing) // omit report for the typical initial case
-        esyslog("cAudioRepacker: skipped %d bytes while syncing on next audio frame", skippedBytes - SkippedBytesLimit);
+        esyslog("cAudioRepacker(0x%02X): skipped %d bytes while syncing on next audio frame", cid, skippedBytes - SkippedBytesLimit);
      skippedBytes = SkippedBytesLimit;
      }
 }
 
 int cAudioRepacker::BreakAt(const uchar *Data, int Count)
 {
+  if (initiallySyncing)
+     return -1; // fill the packet buffer completely until we have synced once
+
   int PesPayloadOffset = 0;
 
   ePesHeader MpegLevel = AnalyzePesHeader(Data, Count, PesPayloadOffset);
@@ -1189,6 +1284,9 @@  void cDolbyRepacker::Repack(cRingBufferL
 
 int cDolbyRepacker::BreakAt(const uchar *Data, int Count)
 {
+  if (initiallySyncing)
+     return -1; // fill the packet buffer completely until we have synced once
+
   // enough data for test?
   if (Count < 6 + 3)
      return -1;
@@ -1514,8 +1612,10 @@  void cTS2PES::instant_repack(const uint8
                         }
                      if (mpeg == 1) {
                         if (flag1 == 0xFF) { // MPEG1 stuffing
-                           if (++mpeg1_stuffing > 16)
+                           if (++mpeg1_stuffing > 16) {
                               found = 0; // invalid MPEG1 header
+                              esyslog("instant_repack: invalid MPEG1 header: stuffing");
+                              } 
                            else { // ignore stuffing
                               found--;
                               if (plength > 0)
@@ -1524,8 +1624,10 @@  void cTS2PES::instant_repack(const uint8
                            }
                         else if ((flag1 & 0xC0) == 0x40) // STD_buffer_scale/size
                            mpeg1_required += 2;
-                        else if (flag1 != 0x0F && (flag1 & 0xF0) != 0x20 && (flag1 & 0xF0) != 0x30)
+                        else if (flag1 != 0x0F && (flag1 & 0xF0) != 0x20 && (flag1 & 0xF0) != 0x30) {
                            found = 0; // invalid MPEG1 header
+                           esyslog("instant_repack: invalid MPEG1 header: required 7");
+                           } 
                         else {
                            flag2 = 0;
                            hlength = 0;
@@ -1543,8 +1645,10 @@  void cTS2PES::instant_repack(const uint8
                   if (!done && (mpeg == 2 || mpeg1_required > 7)) {
                      hlength = Buf[c++];
                      found++;
-                     if (mpeg == 1 && hlength != 0x0F && (hlength & 0xF0) != 0x20 && (hlength & 0xF0) != 0x30)
+                     if (mpeg == 1 && hlength != 0x0F && (hlength & 0xF0) != 0x20 && (hlength & 0xF0) != 0x30) {
                         found = 0; // invalid MPEG1 header
+                        esyslog("instant_repack: invalid MPEG1 header: required 9");
+                        } 
                      }
                   break;
           default:
@@ -1625,6 +1729,9 @@  void cTS2PES::ts_to_pes(const uint8_t *B
   if (!Buf)
      return;
 
+  if (repacker)
+     repacker->LogTSPacket(Buf);
+
   if (Buf[1] & TS_ERROR)
      tsErrors++;
   if ((Buf[3] ^ ccCounter) & CONT_CNT_MASK) {
@@ -1685,13 +1792,15 @@  cRemux::cRemux(int VPid, const int *APid
 #endif
   if (APids) {
      int n = 0;
-     while (*APids && numTracks < MAXTRACKS && n < MAXAPIDS)
+     while (*APids && numTracks < MAXTRACKS && n < MAXAPIDS) {
 #define TEST_cAudioRepacker
 #ifdef TEST_cAudioRepacker
-           ts2pes[numTracks++] = new cTS2PES(*APids++, resultBuffer, IPACKS, 0xC0 + n++, 0x00, new cAudioRepacker);
+           ts2pes[numTracks++] = new cTS2PES(*APids++, resultBuffer, IPACKS, 0xC0 + n, 0x00, new cAudioRepacker(0xC0 + n));
+           n++;
 #else
            ts2pes[numTracks++] = new cTS2PES(*APids++, resultBuffer, IPACKS, 0xC0 + n++);
 #endif
+           }
      }
   if (DPids) {
      int n = 0;