INVITATION: help debugging cAudioRepacker

Message ID 43196315.4090603@gmx.de
State New
Headers

Commit Message

Reinhard Nissl Sept. 3, 2005, 8:47 a.m. UTC
  Hi,

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.

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.

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

Sebastian Frei Sept. 3, 2005, 9:38 a.m. UTC | #1
Am Samstag 03 September 2005 10:47 schrieb Reinhard Nissl:
> Hi,
>
> 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
>

>
> 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.
>
I have a NPTL-only system without the possibility to use 
LD_ASSUME_KERNEL=2.4.1, but I have also the messages above. 

Can I debug another way ?

S.
  
Reinhard Nissl Sept. 3, 2005, 11:12 a.m. UTC | #2
Hi,

Sebastian Frei 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
>> 
>>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.
>
> I have a NPTL-only system without the possibility to use 
> LD_ASSUME_KERNEL=2.4.1, but I have also the messages above. 
> 
> Can I debug another way ?

Well, you'd have to add pid and tid to each debug message, like in 
cThread::StartThread().

For example

esyslog("cAudioRepacker(0x%02X, pid=%d, tid=%ld): ...", cid, getpid(), 
pthread_self(), ...);

Please excuse my lazyness for not having done it already :-(

Bye.
  

Patch

--- ../vdr-1.3.31-orig/remux.c	2005-08-28 13:46:44.000000000 +0200
+++ remux.c	2005-09-02 23:13:50.000000000 +0200
@@ -142,7 +142,7 @@  void cCommonRepacker::Reset(void)
 {
   cRepacker::Reset();
   skippedBytes = 0;
-  packetTodo = maxPacketSize - 6 - 3;
+  packetTodo = 0;
   fragmentLen = 0;
   pesHeaderLen = 0;
   pesHeaderBackupLen = 0;
@@ -361,7 +361,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 +468,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)
@@ -513,9 +516,10 @@  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);
 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 +540,9 @@  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)
 {
+  cid = Cid;
   Reset();
 }
 
@@ -566,23 +571,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 +672,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,10 +682,14 @@  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) {
+           int LastFrameSize = frameSize;
            if (frameTodo <= 0 && IsValidAudioHeader(scanner, mpegLevel == phMPEG2, &frameSize)) {
               if (state == scanFrame) {
                  // As a new audio frame starts here, the previous one is done. So push
@@ -678,10 +702,15 @@  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);
+                    }
                  skippedBytes = 0;
                  // if there is a PES header available, then use it ...
                  if (pesHeaderBackupLen > 0) {
@@ -728,11 +757,13 @@  void cAudioRepacker::Repack(cRingBufferL
                  }
               }
            }
+        else if (skippedBytes == SkippedBytesLimit)
+           esyslog("cAudioRepacker(0x%02X): no valid audio frame header (0x%08X) at expected location", cid, scanner);
         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 +860,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 +1223,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 +1551,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 +1563,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 +1584,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:
@@ -1685,13 +1728,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;