hi,
I am using vdr 1.3.25 unpatched with the latest beta firmware 261e. This is what I get after having added a little bit more debug output showing the SubStreamType.
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
I'd say there is a bug in vdr which triggers a bug in the firmware (assuming the firmware should never hang on wrong input)
Also, are those messages "SetBrokenLink..." really needed for pure audio records?
vdr ignores timeouts on OSDSetBlock and similar functions. Shouldn't it rather do something like restart itself and the driver? (up to now the driver never returned error codes for these functions but the CVS drivers now do so)
Jun 15 03:19:28 mm vdr[28881]: playing '/var/lib/video/ARD-Nachtkonzert/2005-04-15.02.04.50.50.rec/001.vdr' Jun 15 03:19:28 mm vdr[29121]: dvbplayer thread started (pid=29121, tid=147463) Jun 15 03:19:28 mm vdr[29121]: resuming replay at index 25211 (0:16:48.12) Jun 15 03:19:28 mm vdr[29122]: non blocking file reader thread started (pid=29122, tid=163848) Jun 15 03:19:28 mm vdr[29121]: SetBrokenLink: no video packet in frame Jun 15 03:19:28 mm vdr[29121]: setting audio track to 33 Jun 15 03:19:36 mm vdr[29121]: SetBrokenLink: no video packet in frame Jun 15 03:19:37 mm vdr[29121]: switching to pre 1.3.19 Dolby Digital compatibility mode,SubStreamType:176 Jun 15 03:19:37 mm vdr[29121]: setting audio track to 33 Jun 15 03:19:45 mm vdr[29121]: ERROR: incomplete PES packet write! Jun 15 03:19:46 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 // -110 is -ETIMEDOUT Jun 15 03:19:46 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110
Jun 15 03:17:33 mm vdr[27579]: SetBrokenLink: no video packet in frame Jun 15 03:17:35 mm vdr[27579]: SetBrokenLink: no video packet in frame Jun 15 03:17:35 mm vdr[27579]: switching to pre 1.3.19 Dolby Digital compatibility mode,SubStreamType:0 Jun 15 03:17:35 mm vdr[27579]: setting audio track to 33 Jun 15 03:17:37 mm vdr[27579]: SetBrokenLink: no video packet in frame Jun 15 03:18:32 mm vdr[27580]: non blocking file reader thread ended (pid=27580, tid=163848) Jun 15 03:18:33 mm vdr[27579]: dvbplayer thread ended (pid=27579, tid=147463) Jun 15 03:18:33 mm vdr[27517]: switching to channel 2 Jun 15 03:18:33 mm vdr[27973]: transfer thread started (pid=27973, tid=180231) Jun 15 03:18:33 mm vdr[27974]: receiver on device 1 thread started (pid=27974, tid=196616) Jun 15 03:18:33 mm vdr[27975]: TS buffer on device 1 thread started (pid=27975, tid=213001) // I believe this is a result of the above bug: Jun 15 03:18:37 mm vdr[27973]: clearing device because of consecutive poll timeouts Jun 15 03:18:38 mm vdr[27973]: clearing device because of consecutive poll timeouts Jun 15 03:18:39 mm vdr[27973]: clearing device because of consecutive poll timeouts
On Wed, Jun 15, 2005 at 03:42:40AM +0200, Wolfgang Rohdewald wrote:
hi,
I am using vdr 1.3.25 unpatched with the latest beta firmware 261e. This is what I get after having added a little bit more debug output showing the SubStreamType.
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
Does this also happen with 261d ?
Werner
On Mittwoch 15 Juni 2005 11:41, Dr. Werner Fink wrote:
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
Does this also happen with 261d ?
yes.
If you try to reproduce it, don't do it near the beginning of the recording.
On Wed, Jun 15, 2005 at 02:28:16PM +0200, Wolfgang Rohdewald wrote:
On Mittwoch 15 Juni 2005 11:41, Dr. Werner Fink wrote:
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
Does this also happen with 261d ?
yes.
If you try to reproduce it, don't do it near the beginning of the recording.
And really both firmware hang and will be reseted by the driver after 5 seconds? Or do they only stop replaying in other words do waiting for new commands or data (aka no ARM crash)?
Werner
On Mittwoch 15 Juni 2005 14:49, Dr. Werner Fink wrote:
On Wed, Jun 15, 2005 at 02:28:16PM +0200, Wolfgang Rohdewald wrote:
On Mittwoch 15 Juni 2005 11:41, Dr. Werner Fink wrote:
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
Does this also happen with 261d ?
yes.
If you try to reproduce it, don't do it near the beginning of the recording.
And really both firmware hang and will be reseted by the driver after 5 seconds? Or do they only stop replaying in other words do waiting for new commands or data (aka no ARM crash)?
you are right in that the firmware does not reset. However the behaviour is rather unpredictable afterwards. Especially if OSDSetBlock times out it will sometimes not recover: (this example was with 261e)
Jun 15 14:59:24 mm vdr[30159]: SetBrokenLink: no video packet in frame Jun 15 14:59:24 mm vdr[30159]: setting audio track to 33 Jun 15 14:59:29 mm vdr[30159]: SetBrokenLink: no video packet in frame Jun 15 14:59:30 mm vdr[30159]: switching to pre 1.3.19 Dolby Digital compatibility mode,SubStreamType:0 Jun 15 14:59:30 mm vdr[30159]: setting audio track to 33 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1834 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1835 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1836 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1837 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1838 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1839 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1840 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1841 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1842 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1843 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1844 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1845 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1846 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:35 mm vdr[30101]: changing transponder data of channel 1847 from S19.2E:12825:v:27500:3 to S19.2E:12285:v:27500:3 Jun 15 14:59:40 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 14:59:40 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 14:59:40 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 14:59:43 mm vdr[30159]: ERROR: incomplete PES packet write! Jun 15 14:59:50 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 14:59:50 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 14:59:50 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 15:00:00 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 15:00:00 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 15:00:00 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 15:00:18 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 15:00:18 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 15:00:18 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 15:00:18 mm vdr[30159]: SetBrokenLink: no video packet in frame Jun 15 15:00:28 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 15:00:28 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 15:00:28 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 15:00:38 mm vdr[30097]: connect from 10.13.1.99, port 59922 - accepted Jun 15 15:00:38 mm vdr[30097]: SVDRP message: 'Raimar Sauer: AW: SF9701 huber Dru' Jun 15 15:00:38 mm vdr[30097]: closing SVDRP connection Jun 15 15:00:38 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 15 15:00:38 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 15 15:00:38 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 15 15:00:38 mm vdr[30097]: switching to channel 3 Jun 15 15:00:38 mm vdr[30160]: non blocking file reader thread ended (pid=30160, tid=163848) Jun 15 15:00:38 mm vdr[30159]: dvbplayer thread ended (pid=30159, tid=147463) Jun 15 15:00:43 mm kernel: dvb-ttpci: ReleaseBitmap(): ReleaseBitmap called while BMP_LOADING Jun 15 15:00:43 mm kernel: dvb-ttpci: OSDSetBlock(): returns -512 Jun 15 15:00:43 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -ERESTARTSYS Jun 15 15:00:52 mm kernel: dvb-ttpci: ReleaseBitmap(): ReleaseBitmap called while BMP_LOADING Jun 15 15:00:52 mm kernel: dvb-ttpci: OSDSetBlock(): returns -512 Jun 15 15:00:52 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -ERESTARTSYS Jun 15 15:01:03 mm kernel: saa7146: unregister extension 'budget_ci dvb'.
On Wed, Jun 15, 2005 at 04:56:05PM +0200, Wolfgang Rohdewald wrote:
On Mittwoch 15 Juni 2005 14:49, Dr. Werner Fink wrote:
On Wed, Jun 15, 2005 at 02:28:16PM +0200, Wolfgang Rohdewald wrote:
On Mittwoch 15 Juni 2005 11:41, Dr. Werner Fink wrote:
The SubStreamType found varies. The record is not pre 1.3.19.
This happens _only_ after fastrewind/play, fastforward/play works correctly.
Does this also happen with 261d ?
yes.
If you try to reproduce it, don't do it near the beginning of the recording.
And really both firmware hang and will be reseted by the driver after 5 seconds? Or do they only stop replaying in other words do waiting for new commands or data (aka no ARM crash)?
you are right in that the firmware does not reset. However the behaviour is rather unpredictable afterwards. Especially if OSDSetBlock times out it will sometimes not recover: (this example was with 261e)
IMHO the firmware status is not that what the driver belive it is. Maybe a VIDEO_CLEAR_BUFFER and/or AUDIO_CLEAR_BUFFER send to the firmware with COMTYPE_REC_PLAY+__Play was not stopped afterwards because there is no thread/process which can be woken up for this or the playing state is gone in the driver without sending COMTYPE_REC_PLAY+__Stop? If this really happen the firmware will ask the driver for getting data to be played and this will slow down the BMP upload and all OSD commands.
But this is only a guess.
Werner
On Mittwoch 15 Juni 2005 17:15, Dr. Werner Fink wrote:
IMHO the firmware status is not that what the driver belive it is. Maybe a VIDEO_CLEAR_BUFFER and/or AUDIO_CLEAR_BUFFER send to the firmware with COMTYPE_REC_PLAY+__Play was not stopped afterwards because there is no thread/process which can be woken up for this or the playing state is gone in the driver without sending COMTYPE_REC_PLAY+__Stop? If this really happen the firmware will ask the driver for getting data to be played and this will slow down the BMP upload and all OSD commands.
more debug output: If I repeatedly fastrewind/play, __Stop is never called in between. Do you mean it should?
OTOH could the reason for the problems be that audio AND video is replayed for a recording that has no video? What does AUDIO_SET_AV_SYNC do then?
Jun 16 00:08:14 mm vdr[24123]: replay /var/lib/video/ARD-Nachtkonzert/2005-04-15.02.04.50.50.rec Jun 16 00:08:14 mm vdr[24123]: playing '/var/lib/video/ARD-Nachtkonzert/2005-04-15.02.04.50.50.rec/001.vdr' Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28425 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CHANNEL_SELECT Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28422 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_MUTE Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28442 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28442 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28421 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SELECT_SOURCE Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28418 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_PLAY Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:COMTYPE_REC_PLAY __Stop Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:RP_AUDIO:COMTYPE_REC_PLAY __Play Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl returns 2 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28441 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28438 Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:COMTYPE_REC_PLAY __Stop Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:RP_AV:COMTYPE_REC_PLAY __Play Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl returns 3 Jun 16 00:08:14 mm vdr[24294]: dvbplayer thread started (pid=24294, tid=294927) Jun 16 00:08:14 mm vdr[24294]: resuming replay at index 27784 (0:18:31.10) Jun 16 00:08:14 mm vdr[24295]: non blocking file reader thread started (pid=24295, tid=311312) Jun 16 00:08:15 mm vdr[24294]: SetBrokenLink: no video packet in frame Jun 16 00:08:15 mm vdr[24294]: setting audio track to 33 Jun 16 00:10:00 mm vdr[24163]: TS buffer on device 2 thread ended (pid=24163, tid=196621) Jun 16 00:10:00 mm vdr[24162]: buffer stats: 86292 (4%) used Jun 16 00:10:00 mm vdr[24162]: receiver on device 2 thread ended (pid=24162, tid=180236) Jun 16 00:10:00 mm vdr[24160]: file writer thread ended (pid=24160, tid=147466) Jun 16 00:10:00 mm vdr[24123]: buffer stats: 91744 (1%) used Jun 16 00:10:00 mm vdr[24123]: timer 5 (3 2208-0010 'stern TV') stop GJun 16 00:10:44 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28422 Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_MUTE Jun 16 00:10:44 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28448 Jun 16 00:10:44 mm vdr[24294]: SetBrokenLink: no video packet in frame Jun 16 00:10:46 mm vdr[24294]: switching to pre 1.3.19 Dolby Digital compatibility mode,SubStreamType:0 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28425 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CHANNEL_SELECT Jun 16 00:10:46 mm vdr[24294]: setting audio track to 33 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Slow,2,0 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:10:46 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28440 Jun 16 00:10:46 mm vdr[24294]: SetBrokenLink: no video packet in frame Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28422 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_MUTE Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28448 Jun 16 00:13:57 mm vdr[24294]: SetBrokenLink: no video packet in frame Jun 16 00:14:09 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:09 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:09 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:18 mm vdr[24294]: ERROR: incomplete PES packet write! Jun 16 00:14:19 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:19 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:19 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:29 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:29 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:29 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:39 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Slow,2,0 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28440 Jun 16 00:14:39 mm vdr[24294]: SetBrokenLink: no video packet in frame Jun 16 00:14:49 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:49 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:49 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110
On Thu, Jun 16, 2005 at 12:49:18AM +0200, Wolfgang Rohdewald wrote:
On Mittwoch 15 Juni 2005 17:15, Dr. Werner Fink wrote:
IMHO the firmware status is not that what the driver belive it is. Maybe a VIDEO_CLEAR_BUFFER and/or AUDIO_CLEAR_BUFFER send to the firmware with COMTYPE_REC_PLAY+__Play was not stopped afterwards because there is no thread/process which can be woken up for this or the playing state is gone in the driver without sending COMTYPE_REC_PLAY+__Stop? If this really happen the firmware will ask the driver for getting data to be played and this will slow down the BMP upload and all OSD commands.
more debug output: If I repeatedly fastrewind/play, __Stop is never called in between. Do you mean it should?
OTOH could the reason for the problems be that audio AND video is replayed for a recording that has no video? What does AUDIO_SET_AV_SYNC do then?
Nothing I guess ;)
Jun 16 00:08:14 mm vdr[24123]: replay /var/lib/video/ARD-Nachtkonzert/2005-04-15.02.04.50.50.rec Jun 16 00:08:14 mm vdr[24123]: playing '/var/lib/video/ARD-Nachtkonzert/2005-04-15.02.04.50.50.rec/001.vdr'
One problem I see is stopping a running replay. After receiving and executing the __Stop request the firmware goes two steps: first it waits on a free TX slot, if it get one it performs an empty TX request (debitype = DATA_MPEG_PLAY and debilen = 0 -> gpioirq()). Note if the command and OSD queue is filled there is a delay between receiving and executing commands.
Now you can slow down this two steps by Bitmap uploads and if the firmware is receiving a __Play or __Stop and executing this within those two steps the __Play or __Stop commands are simply lost (which maybe leads t oa wrong state in the driver). Also the execution of any other command, e.g. COMTYPE_REC_PLAY can be slowed down by Bitmap uploads and other OSD commands.
IMHO there should be used a wait queue or similar which could be used to sleep on after sending a COMTYPE_REC_PLAY+__Stop to be waken if in the gpioirq() the debilen == 0 for DATA_MPEG_PLAY is seen.
Timeout should be in the same region as used for checking the ARM state ... clearly if the ARM is crashed, then all sleepers should be also waken. Also within a threaded environment all other threads/programs calling a COMTYPE_REC_PLAY afterwords have to sleep together with the first caller.
Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_PLAY Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:COMTYPE_REC_PLAY __Stop Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:RP_AUDIO:COMTYPE_REC_PLAY __Play Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl returns 2 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28441 Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28438 Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:COMTYPE_REC_PLAY __Stop Jun 16 00:08:14 mm kernel: dvb-ttpci: av7110_av_start_play(): av7110_av_start_play:RP_AV:COMTYPE_REC_PLAY __Play
Jun 16 00:08:14 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl returns 3 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28422 Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_MUTE Jun 16 00:13:57 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28448
Jun 16 00:14:09 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:09 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:09 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:19 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:19 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:19 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:29 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:29 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:29 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:39 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28450 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): dvb_video_ioctl:VIDEO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Slow,2,0 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28428 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_CLEAR_BUFFER Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): dvb_audio_ioctl:AUDIO_CLEAR_BUFFER:COMTYPE_REC_PLAY,__Play,2,AV_PES Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): av7110:cbcd8000, cmd=28423 Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_audio_ioctl(): AUDIO_SET_AV_SYNC Jun 16 00:14:39 mm kernel: dvb-ttpci: dvb_video_ioctl(): av7110:cbcd8000, cmd=28440 Jun 16 00:14:49 mm kernel: dvb-ttpci: warning: timeout waiting in LoadBitmap: 0, 1 Jun 16 00:14:49 mm kernel: dvb-ttpci: OSDSetBlock(): returns -110 Jun 16 00:14:49 mm kernel: dvb-ttpci: av7110_osd_cmd(): av7110_osd_cmd(13) returns with -110
Werner
-
Dr. Werner Fink -
Wolfgang Rohdewald