From patchwork Sat Sep 3 20:16:45 2005 Content-Type: text/plain; charset="utf-8" MIME-Version: 1.0 Content-Transfer-Encoding: 7bit X-Patchwork-Submitter: Reinhard Nissl X-Patchwork-Id: 12006 Received: from mail.gmx.de ([213.165.64.20] helo=mail.gmx.net) by www.linuxtv.org with smtp (Exim 4.34) id 1EBeS0-0001TX-TN for vdr@linuxtv.org; Sat, 03 Sep 2005 22:17:20 +0200 Received: (qmail invoked by alias); 03 Sep 2005 20:16:47 -0000 Received: from Af396.a.pppool.de (EHLO [192.168.101.15]) [213.6.243.150] by mail.gmx.net (mp008) with SMTP; 03 Sep 2005 22:16:47 +0200 X-Authenticated: #527675 Message-ID: <431A04AD.4090901@gmx.de> Date: Sat, 03 Sep 2005 22:16:45 +0200 From: Reinhard Nissl User-Agent: Mozilla Thunderbird 1.0.6 (X11/20050716) X-Accept-Language: en-us, en MIME-Version: 1.0 To: Klaus Schmidinger's VDR Subject: Re: [vdr] [INVITATION] help debugging cAudioRepacker References: <43196315.4090603@gmx.de> In-Reply-To: <43196315.4090603@gmx.de> X-Y-GMX-Trusted: 0 X-BeenThere: vdr@linuxtv.org X-Mailman-Version: 2.1.5 Precedence: list Reply-To: Klaus Schmidinger's VDR List-Id: Klaus Schmidinger's VDR List-Unsubscribe: , List-Archive: List-Post: List-Help: List-Subscribe: , X-List-Received-Date: Sat, 03 Sep 2005 20:17:20 -0000 Status: O X-Status: X-Keywords: X-UID: 4733 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. --- ../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;