[pvrusb2] Re: Problem with 20060102A
Mike Isely
isely at isely.net
Wed Jan 4 21:50:26 CST 2006
Comments interleaved...
On Wed, 4 Jan 2006, Helmut Toplitzer wrote:
>
> Ok. Testing gmplayer works fine so far. However sometimes stop/starting
> takes longer than others. Then, it looks like, the device is reset:
>
> vrusb2 i2c v4l2 decoder_enable(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_start id=cad1e980
> pvrusb2 /*--TRACE_STREAM--*/ disable
> pvrusb2 subsys mask changing 0x3c000:0x0 from 0x3c001 to 0x1
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_stop
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(0)
> pvrusb2 /*---TRACE_CTL----*/ decoder disable
> pvrusb2 i2c v4l2 decoder_enable(0)
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (tear-down) id=cad1e980
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_stop id=cad1e980
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (setup) id=cad1e980
> pvrusb2 /*--TRACE_STREAM--*/ enable
> pvrusb2 subsys mask changing 0x3c001:0xffffffff from 0x1 to 0x3c001
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_configure
> pvrusb2 /*---TRACE_CTL----*/ decoder enable
> pvrusb2 i2c v4l2 decoder_enable(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 ***WARNING*** device's encoder appears to be stuck (status=000000003)
> pvrusb2 Encoder command: 0x81
> pvrusb2 Encoder arg1: 0x00000000
> pvrusb2 Encoder arg2: 0x00000013
> pvrusb2 Encoder arg3: 0x00000000
> pvrusb2 Encoder arg4: 0x00000000
> pvrusb2 Encoder arg5: 0x00000000
> pvrusb2 Encoder arg6: 0x00000000
> pvrusb2 Encoder arg7: 0x00000000
> pvrusb2 Encoder arg8: 0x00000000
> pvrusb2 Encoder arg9: 0x00000000
> pvrusb2 Encoder arg10: 0x00000000
> pvrusb2 Encoder arg11: 0x00000000
> pvrusb2 Encoder arg12: 0x00000000
> pvrusb2 Giving up waiting. It is likely that this is a bad idea...
> pvrusb2 Error recovery initiated
> pvrusb2 Retrying device reconfiguration
> pvrusb2 subsys mask changing 0x3c001:0xffffffff from 0x8000 to 0x3c001
Ah yes, I should have remembered that. The initial log you sent didn't
show this sort of reset taking place, but I can add some info to this.
Every once in a while the encoder just "stops responding". There is a
handshake that the pvrusb2 driver must do with the encoder every time a
command is issued to it. I did a lot of experiments with this last June /
July back when I was fighting an encoder stability problem (which turned
out to be something else entirely). What I found was that once the
encoder gets into this state it will remain permanently stuck until its
firmware is reloaded. (No, the timeout isn't too short - I tried some
obnoxiously long time intervals - tens of seconds - and the encoder really
truly is stuck when this happens.)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_upload_firmware2
> pvrusb2 pvr2_upload_firmware2
> pvrusb2 Requesting uproc soft reset
> pvrusb2 Requesting uproc hard reset
> pvrusb2 upload of pvrusb2.f2 : 262144 / 262144
And here we see the pvrusb2 driver recovering the encoder by reloading its
firmware. This usually happens pretty quick and it is SUPPOSED to be
fairly rare. But certainly this is going to cause streaming to break for
a few moments while the driver repairs the damage.
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_configure
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_start id=cad1e980
>
> But its working again after this without any action on my side.
> This also happens sometimes on mythtv without problems (This are the 2sec.
> changes of the channel)
Right, and now that the encoder has been reloaded, it is restarted and
everyone is happy again.
It *sounds* like while this could be adding some delay to changing the
channel, that it isn't coincident with the MythTV hangs you are seeing.
Please correct me if I'm wrong here.
It would be really useful if we could correlate the problems you see with
the encoder being reloaded. You mentioned before that using the 2.6.15
vanilla msp3400 module made this more likely. That would therefore
suggest (if encoder reloading is to blame) that something involving the
msp3400 operation is making it more likely for the encoder to hang. If we
could correlate that then it might be possible to get some traction on
this problem.
Up until now, I have never been able to establish any kind of cause /
effect relationship that might predict when the encoder is likely to hang.
The best I've been able to do is build some recovery into the driver for
when it does hang.
>
> Retested mythtv and got:
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Saturation" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Brightness" <-- 127 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Hue" <-- 0 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Tuner Frequency (Hz)" <-- 495250000 (<integer>)
> pvrusb2 i2c v4l2 set_freq(495250000)
> pvrusb2 i2c v4l1 set_freq(495250000)
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (setup) id=cad1e980
> pvrusb2 /*--TRACE_STREAM--*/ enable
> pvrusb2 subsys mask changing 0x3c001:0xffffffff from 0x1 to 0x3c001
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_configure
> pvrusb2 /*---TRACE_CTL----*/ decoder enable
> pvrusb2 i2c v4l2 decoder_enable(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_start id=cad1e980
The line above shows that streaming was going. The next line shows that
streaming is being stopped.
> pvrusb2 /*--TRACE_STREAM--*/ disable
> pvrusb2 subsys mask changing 0x3c000:0x0 from 0x3c001 to 0x1
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_stop
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(0)
> pvrusb2 /*---TRACE_CTL----*/ decoder disable
> pvrusb2 i2c v4l2 decoder_enable(0)
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (tear-down) id=cad1e980
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_stop id=cad1e980
> pvrusb2 /*--TRACE_COMMIT--*/ "Contrast" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Saturation" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Brightness" <-- 127 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Hue" <-- 0 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Tuner Frequency (Hz)" <-- 543250000 (<integer>)
> pvrusb2 i2c v4l2 set_freq(543250000)
> pvrusb2 i2c v4l1 set_freq(543250000)
Up to this point it appears that the application has gone through 2 steps
to change the frequency. It halted streaming and then it issued V4L
ioctl()'s to change the frequency and reset the brightness / contrast /
saturation / hue. The driver by the way can make those changes without
having to stop the stream. Given that the stream is being stopped anyway
suggests that it is explicitly being stopped from the outside. I believe
MythTV does this. There is nothing wrong here, just an observation here
that when you change frequencies in MythTV, streaming is being stopped /
started.
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (setup) id=cad1e980
> pvrusb2 /*--TRACE_STREAM--*/ enable
> pvrusb2 subsys mask changing 0x3c001:0xffffffff from 0x1 to 0x3c001
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_configure
> pvrusb2 /*---TRACE_CTL----*/ decoder enable
> pvrusb2 i2c v4l2 decoder_enable(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_start id=cad1e980
Here's another break in streaming, starting at this point.
> pvrusb2 /*--TRACE_STREAM--*/ disable
> pvrusb2 subsys mask changing 0x3c000:0x0 from 0x3c001 to 0x1
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_stop
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(0)
> pvrusb2 /*---TRACE_CTL----*/ decoder disable
> pvrusb2 i2c v4l2 decoder_enable(0)
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (tear-down) id=cad1e980
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_stop id=cad1e980
> pvrusb2 /*--TRACE_COMMIT--*/ "Contrast" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Saturation" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Brightness" <-- 127 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Hue" <-- 0 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Tuner Frequency (Hz)" <-- 495250000 (<integer>)
> pvrusb2 i2c v4l2 set_freq(495250000)
> pvrusb2 i2c v4l1 set_freq(495250000)
Ah, another changing of the channel, same as before.
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (setup) id=cad1e980
> pvrusb2 /*--TRACE_STREAM--*/ enable
> pvrusb2 subsys mask changing 0x3c001:0xffffffff from 0x1 to 0x3c001
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_configure
> pvrusb2 /*---TRACE_CTL----*/ decoder enable
> pvrusb2 i2c v4l2 decoder_enable(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(1)
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_start
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_start id=cad1e980
> ================ HERE'S THE HANG ===================================
Comparing this channel change to the previous one, the steps in the log
are exactly the same. So nothing there to suggest a clue. If you can
include high res timestamps with these log entries (it's a kernel config
option) that might provide additional information about something that
might be taking too long.
> ================ RESTARTING MYTHTV - BACKEND =======================
And it's interesting that through the hang, the driver appeared to still
have streaming enabled. No idea if any data was flowing (or any reason
why it wouldn't be flowing). After you kicked the backend here, probably
/dev/video0 (or whatever) got closed by the kernel and that caused the
sequence below which shut down the stream again.
> pvrusb2 /*--TRACE_STREAM--*/ disable
> pvrusb2 subsys mask changing 0x3c000:0x0 from 0x3c001 to 0x1
> pvrusb2 /*---TRACE_CTL----*/ pvr2_encoder_stop
> pvrusb2 /*---TRACE_CTL----*/ pvr2_hdw_cmd_usbstream(0)
> pvrusb2 /*---TRACE_CTL----*/ decoder disable
> pvrusb2 i2c v4l2 decoder_enable(0)
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_setup (tear-down) id=cad1e980
> pvrusb2 /*---TRACE_READ---*/ pvr2_ioread_stop id=cad1e980
>From this point it looks like we're starting up again.
> pvrusb2 pvr2_v4l2_do_ioctl failure, ret=-22 (0xffffffea)
> pvrusb2 /*--TRACE_COMMIT--*/ "Video Source" <-- 0 (television)
> pvrusb2 i2c msp3400 set_stereo
> pvrusb2 i2c v4l2 set_input(0)
> pvrusb2 /*--TRACE_COMMIT--*/ "Video Standard" <-- 1 (PAL-BG)
> pvrusb2 i2c v4l2 set_standard(1)
> pvrusb2 i2c v4l1 set_standard(1)
> pvrusb2 /*--TRACE_COMMIT--*/ "Contrast" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Saturation" <-- 63 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Brightness" <-- 127 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Hue" <-- 0 (<integer>)
> pvrusb2 i2c v4l2 set_bcsh b=127 c=63 s=63 h=0
> pvrusb2 /*--TRACE_COMMIT--*/ "Tuner Frequency (Hz)" <-- 495250000 (<integer>)
> pvrusb2 i2c v4l2 set_freq(495250000)
> pvrusb2 i2c v4l1 set_freq(495250000)
>
>
>> One other question - when you get this hang, how do you recover? Just
>> change channels again, restart MythTV, reload the driver, re-plug the
>> hardware, and/or reboot? Given that the log you sent didn't show any
>> evidence of a problem I have to presume that just causing the stream to
>> restart is probably enough, but everything I've presumed about your issue
>> so far has been wrong :-)
>
> Recovery is done by simply restarting the mythtv-backend. The frontend hangs,
> sometimes quits itself after a few secs., sometimes must be killed.
> Restarting only the frontend is not enough because backend is hung in a way
> too. However the init-script does its work in restarting the backend.
>
> start-stop-daemon --stop --oknodo --pidfile $RUNDIR/$NAME.pid \
> --chuid $USER --exec $DAEMON -- $ARGS
> start-stop-daemon --start --pidfile $RUNDIR/$NAME.pid \
> --chuid $USER --nicelevel $NICE --exec $DAEMON -- $ARGS
>
Unfortunately MythTV does not handle error legs very well overall. I
think this is one of the biggest weaknesses of that entire project.
Before getting into this driver work I ended up chasing down a MythTV
problem that turned out to be a case where I had asked the capture board
to do something it wasn't capable of handling (capture at too high of a
resolution). The MythTV backend ignored the resulting error from the V4L
driver and tried to use the incorrectly mmap()'ed buffer, whereupon the
backend got smacked down by a SEGV for touching unmapped memory. I
pointed this out at the time and the author seemed to have no interest in
repairing this problem since the match that lit this can of gasoline came
from the V4L driver. I pointed out that no program should ever react to
errors by crashing in some strange way, especially a program which is
supposed to run 24x7 like the MythTV backend. This was about the point
when I gave up trying to help out; clearly I wasn't helping very well.
Anyway, the whole point here is that we might have something genuine going
wrong at the pvrusb2 level. Unfortunately debugging this sort of problem
through MythTV is going to be a major pain. It would be an enormous help
if you (or anyone) could reproduce the problem with a simpler application,
like mplayer.
>
> (The second error log included here is hopefully more usefull)
Definitely more information. Right now I'm thinking the encoder reset was
an unlucky coincidence since the hang you marked happened several
streaming-cycles later. If I ever manage to reproduce this problem I'll
let you know.
-Mike
--
| Mike Isely | PGP fingerprint
Spammers Die!! | | 03 54 43 4D 75 E5 CC 92
| isely @ pobox (dot) com | 71 16 01 E2 B5 F5 C1 E8
| |
More information about the pvrusb2
mailing list