FF card AV sync problems, possible fix to VDR (fwd)

Message ID 45DA1020.3090901@gmx.de
State New
Headers

Commit Message

Reinhard Nissl Feb. 19, 2007, 9:01 p.m. UTC
  Hi,

Kartsa wrote:

> My log is actually full of these.

The attached patch adds a TS packet logger to cAudioRepacker, which
stores the last 1000 TS packets that led to synchronization of
cAudioRepacker into a file to /video.

In your logfile you'll then find lines like the following:

Feb 19 21:41:36 video vdr: [9413] cAudioRepacker(0xC1): skipped 24 bytes
to sync on next audio frame
Feb 19 21:41:36 video vdr: [9413] cTSLogger: dumping to file
'/video/ts_9353_9413_0xC1_000_12_12.log'

Please provide me some of these files which were dumped in the "middle"
of a recording. If size matters, you may reduce the number of packets to
100.

Bye.
  

Comments

Reinhard Nissl Feb. 20, 2007, 9:24 p.m. UTC | #1
Hi,

Reinhard Nissl wrote:

> Please provide me some of these files which were dumped in the "middle"
> of a recording. If size matters, you may reduce the number of packets to
> 100.

I had a look into the files you've provided me. It looks like some TS
packets get lost. You can simply check this on your own:

	od -Ax -t x1 -w188 -v ts_10973_11079_0xC0_004_116796_1000.log \
		| tail -n 20 | less -S

will give you something like the lines below (I've croped the long lines
here for readability). Just have a look a the marked column:

                 v
                 v
02d06c 47 02 94 13 24 84 c0 8b
02d128 47 02 94 14 44 91 b9 1b
02d1e4 47 02 94 15 a5 ab ab a1
02d2a0 47 02 94 16 40 b4 0c c2
02d35c 47 02 94 17 5d c5 6b 5f
02d418 47 02 94 18 72 5c 3e 84
02d4d4 47 02 94 19 05 81 b4 7e
02d590 47 02 94 1a 95 ba dc 2c
02d64c 47 02 94 1b 86 86 fe 12
02d708 47 02 94 1c 2b 22 a6 d9
02d7c4 47 02 94 1d b9 b5 e2 6d
02d880 47 02 94 1e e4 6e 11 17
02d93c 47 02 94 1f 90 00 00 00
02d9f8 47 02 94 10 ca 1b 20 ed
02dab4 47 02 94 11 55 d5 c6 73
02db70 47 02 94 10 e8 69 4d 5a
02dc2c 47 02 94 11 d8 e5 9a 69
02dce8 47 02 94 12 ac 2a 65 ba
02dda4 47 02 94 13 62 35 d1 c4
02de60           ^
                 ^

This nibble represents the TS continuity counter. It cycles properly
from 0 to 9 and a to f throughout the file. But near the end the
following sequence appears:

	e f 0 1 . . . . . . . . . . . . . . 0 1 2 3

The dot's indicate at least the missing TS packets with counter values:

	_ _ _ _ 2 3 4 5 6 7 8 9 a b c d e f _ _ _ _

I wonder why you didn't get lines like the following in your logfile
after enabling the earlier mentioned source lines and specifying

	-l 3

on VDR's command line to turn on debug log messages:

Feb 20 21:41:14 video vdr: [27499] TS continuity error (1)
Feb 20 21:41:15 video vdr: [27499] cTS2PES got 0 TS errors, 1 TS
continuity errors

Sad to say, I can hardly help you further as lost TS packets can be
caused by a couple of reasons:

- Dish alignment
- Weather conditions
- Cabling
- Interference with DECT telephones
- DMA/PCI mainboard issues
- High system load / latency
- DVB driver issues

As you can see, VDR just picks up what survived the above stages.

I had lost TS packets over and over just after replacing my PATA drive
by a SATA drive to have the PATA one sent in for repair. I've contacted
the dvb-mailing list and got driver patches for larger DMA buffers.
Extremely large buffers seemed to fix the problem but not completely.
After the PATA drive returned from repair, I've removed the SATA drive
and -- you won't believe it -- everything worked out of the box as
before, even with default drivers (I won't blame here SATA in general --
this is just my personal experience at that time with certain hardware).

BTW: You may wonder why you do not get these messages when watching live
TV with a FF card. The answer is simple: the TS packets never leave the
card in this case, so VDR has no way to report such an issue for example
in case where the problem would be related to dish alignment. But when
you start a recording for example on a single FF card system, TS packets
will then be sent to VDR for the recording and for live TV, so if you
continue to watch the recorded channel, you'll typically get the
cRepacker messages twice for different threads.

Bye.
  
Morfsta Feb. 20, 2007, 9:50 p.m. UTC | #2
OK, so Karsta and I are suffering dropped TS packets. I know for sure that
my DVB-T signal is not perfect so it is likely to occasionally lose some TS
packets (freeview in the UK is susceptible to all sorts of interference from
cars, motorbikes, DECT, etc) however, saying there is nothing that we can do
about this because you don't have a *perfect* DVB signal surely isn't the
right answer! My TV copes perfectly well with dropped packets and doesn't go
out of sync, as does my freeview box. Surely if some TS packets are dropped
this shouldn't result in a loss of sync, the system should resync the audio
and continue as before?? It can't be right to say, well we lost some data,
so we can't recover until you change channels up and down, or
fastforward/rewind by 1 minute!

I have spent the last 2 weeks trying different combinations, playing with my
kernel settings, trying USB DVB-T devices rather than the PCI and it makes
absolutely no difference. The TS continuity errors do not go away so I am
convinced it is simply that DVB-T is not as robust as other signals such as
DVB-S or DVB-C. However, VDR should be able to cope and resync with lost
data.

Regards,

Morfsta
  
Kartsa Feb. 21, 2007, 5:59 p.m. UTC | #3
Reinhard Nissl kirjoitti:
> I had a look into the files you've provided me. It looks like some TS
> packets get lost. You can simply check this on your own:
>
> 	od -Ax -t x1 -w188 -v ts_10973_11079_0xC0_004_116796_1000.log \
> 		| tail -n 20 | less -S
>
> I wonder why you didn't get lines like the following in your logfile
> after enabling the earlier mentioned source lines and specifying
>
> 	-l 3
>
> on VDR's command line to turn on debug log messages:
>
> Feb 20 21:41:14 video vdr: [27499] TS continuity error (1)
> Feb 20 21:41:15 video vdr: [27499] cTS2PES got 0 TS errors, 1 TS
> continuity errors
>   
This has been very illuminating. Maybe I made some mistake with the 
logging because there really is no TS continuity error in the log. I 
definitely have -l 3 on commandline (just checked with ps -ef). And I 
also checked that I had activated the line in remux.c. And I now that I 
have used that remux.c while compiling because it is the same that I 
used your patch against. So I do not know why there is no TS continuity 
errors on log.
> Sad to say, I can hardly help you further as lost TS packets can be
> caused by a couple of reasons:
>
> - Dish alignment
> - Weather conditions
> - Cabling
> - Interference with DECT telephones
> - DMA/PCI mainboard issues
> - High system load / latency
> - DVB driver issues
>   
I am in cable so dish can not be the problem, nor the weather. Cabling 
is one (including the operators cables) and I suspect a hw issue (or 
DMA/PCI) as I have sata drives. Telephones can always be a problem but I 
do not think that this often. High load is not a possibility unless vdr 
is causing the load :) And ofcourse there is the driver. But mostly I 
suspect the cable operators cables because even the analog picture is 
not too good and I get cAudioRepacker skipped messages on my other vdr 
also (but after fifth simultaneous recording). Ofcource the firmware is 
the same. I think I must try the older fw on the other to see if it 
makes any difference.
> As you can see, VDR just picks up what survived the above stages.
>
> I had lost TS packets over and over just after replacing my PATA drive
> by a SATA drive to have the PATA one sent in for repair. I've contacted
> the dvb-mailing list and got driver patches for larger DMA buffers.
> Extremely large buffers seemed to fix the problem but not completely.
> After the PATA drive returned from repair, I've removed the SATA drive
> and -- you won't believe it -- everything worked out of the box as
> before, even with default drivers (I won't blame here SATA in general --
> this is just my personal experience at that time with certain hardware).
>   
This is why I am using different mb model and a pata drive on a new vdr 
I am just building for a friend. I will inform you about how that one works.
> BTW: You may wonder why you do not get these messages when watching live
> TV with a FF card. The answer is simple: the TS packets never leave the
> card in this case, so VDR has no way to report such an issue for example
> in case where the problem would be related to dish alignment.
I have no problems with the live TV. Never had any problems with that.

Anyway thanks for your input and support.

\\Kartsa
  
Halim Sahin Feb. 22, 2007, 9:29 a.m. UTC | #4
Hi,
On Mi, Feb 21, 2007 at 07:59:18 +0200, Kartsa wrote:
> Reinhard Nissl kirjoitti:
> >I had a look into the files you've provided me. It looks like some TS
> >packets get lost. You can simply check this on your own:
> >
> >	od -Ax -t x1 -w188 -v ts_10973_11079_0xC0_004_116796_1000.log \
> >		| tail -n 20 | less -S
> >
> >I wonder why you didn't get lines like the following in your logfile
> >after enabling the earlier mentioned source lines and specifying
> >
> >	-l 3
> >
> This has been very illuminating. Maybe I made some mistake with the 
> logging because there really is no TS continuity error in the log. I 
> definitely have -l 3 on commandline (just checked with ps -ef). And I 

Under debian Systems you must look in to /var/log/syslog and
not in to /var/log/messages.
It depends on your syslog configuration.
Maybe it helps.


Halim
  
Kartsa Feb. 22, 2007, 2:38 p.m. UTC | #5
Halim Sahin kirjoitti:
>> This has been very illuminating. Maybe I made some mistake with the 
>> logging because there really is no TS continuity error in the log. I 
>> definitely have -l 3 on commandline (just checked with ps -ef). And I 
>>     
>
> Under debian Systems you must look in to /var/log/syslog and
> not in to /var/log/messages.
> It depends on your syslog configuration.
> Maybe it helps.
>   
Thanks, but in FC it is /var/log/messages :) And everything else is in 
messages file. There is no syslog file. But it has to be something to do 
with where the messages are at least trying to be written. Maybe I'll 
figure it out some day :)

\\Kartsa
  

Patch

--- ../vdr-1.4.5-orig/remux.c	2006-12-01 15:46:25.000000000 +0100
+++ remux.c	2007-02-19 21:39:41.000000000 +0100
@@ -86,6 +86,65 @@  ePesHeader AnalyzePesHeader(const uchar 
   return phMPEG1; // MPEG 1
 }
 
+// --- cTSLogger -------------------------------------------------------------
+
+class cTSLogger
+{
+  cMutex mutex;
+  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 = 1000; // 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)
+{
+  cMutexLock MutexLock(&mutex);
+
+  memcpy(&buffer[(count++ % size) * 188], Data, 188);
+  if (fill < size)
+     fill++;
+}
+
+void cTSLogger::Dump()
+{
+  cMutexLock MutexLock(&mutex);
+
+  char name[200];
+  sprintf(name, "/video/ts_%d_%d_0x%02X_%03d_%lld_%d.log", getpid(), cThread::ThreadId(), 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;
+}
+
 // --- cRepacker -------------------------------------------------------------
 
 #define MIN_LOG_INTERVAL 10 // min. # of seconds between two consecutive log messages of a cRepacker
@@ -110,6 +169,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) {}
   };
 
 cRepacker::cRepacker(void)
@@ -691,6 +837,8 @@  private:
   int frameSize;
   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(int Cid);
   virtual void Reset(void);
@@ -712,6 +861,7 @@  int cAudioRepacker::bitRates[2][3][16] =
   };
 
 cAudioRepacker::cAudioRepacker(int Cid)
+  : tsLogger(Cid)
 {
   cid = Cid;
   Reset();
@@ -842,8 +1302,10 @@  void cAudioRepacker::Repack(cRingBufferL
               if (state == syncing) {
                  if (initiallySyncing) // omit report for the typical initial case
                     initiallySyncing = false;
-                 else if (skippedBytes > SkippedBytesLimit) // report that syncing dropped some bytes
+                 else if (skippedBytes > SkippedBytesLimit) { // report that syncing dropped some bytes
                     LOG("cAudioRepacker(0x%02X): skipped %d bytes to sync on next audio frame", cid, skippedBytes - SkippedBytesLimit);
+                    tsLogger.Dump();
+                    }
                  skippedBytes = 0;
                  // if there is a PES header available, then use it ...
                  if (pesHeaderBackupLen > 0) {
@@ -1803,6 +2278,8 @@  void cTS2PES::instant_repack(const uint8
 
 void cTS2PES::ts_to_pes(const uint8_t *Buf) // don't need count (=188)
 {
+  if (Buf && repacker) repacker->LogTSPacket(Buf);
+ 
   if (!Buf)
      return;