Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Easycap driver from staging directory doesn't work. #137

Closed
piotr-e opened this issue Oct 16, 2012 · 15 comments
Closed

Easycap driver from staging directory doesn't work. #137

piotr-e opened this issue Oct 16, 2012 · 15 comments

Comments

@piotr-e
Copy link

piotr-e commented Oct 16, 2012

After compiling and running with mplayer i see only green screen.

With other driver for EasyCap i see:

Stk1160 driver:
https://github.com/piotr-e/stk1160-raspberrypi

How resolve this problem?

@popcornmix
Copy link
Collaborator

I'm sorry but a bug report like this isn't going to get looked at.
You can't just point at some code and say it doesn't work.
If you can identify specific problems (like packets getting lost over USB, or errors in the kernel log) then we might have something to look into.

@licaon-kter
Copy link

@piotr-e: you just removed some AC97 stuff and hoped... it just works on the Pi?
attach (pastebin) results of:
*lsusb
*lsmod
*compiler errors/warnings if any
*mplayer log
*dmesg after run

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

lsusb

root@raspberrypi:/home/pi# lsusb
Bus 001 Device 001: ID 1d6b:0002 Linux Foundation 2.0 root hub
Bus 001 Device 002: ID 0424:9512 Standard Microsystems Corp.
Bus 001 Device 003: ID 0424:ec00 Standard Microsystems Corp.
Bus 001 Device 004: ID 05e3:0608 Genesys Logic, Inc. USB-2.0 4-Port HUB
Bus 001 Device 005: ID 05e1:0408 Syntek Semiconductor Co., Ltd STK1160 Video Capture Device
root@raspberrypi:/home/pi#

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

lsmod

root@raspberrypi:/home/pi# lsmod
Module Size Used by
snd_bcm2835 12732 0
snd_usb_audio 93617 0
snd_usbmidi_lib 17939 1 snd_usb_audio
snd_hwdep 5794 1 snd_usb_audio
snd_seq_midi 4566 0
snd_seq_midi_event 6489 1 snd_seq_midi
snd_rawmidi 20634 2 snd_seq_midi,snd_usbmidi_lib
snd_pcm 75458 2 snd_usb_audio,snd_bcm2835
snd_page_alloc 4987 1 snd_pcm
snd_seq 52584 2 snd_seq_midi_event,snd_seq_midi
saa7115 14013 1
snd_seq_device 6316 3 snd_seq,snd_rawmidi,snd_seq_midi
snd_timer 19642 2 snd_seq,snd_pcm
stk1160 19143 0
snd 52567 9 snd_timer,snd_seq_device,snd_seq,snd_pcm,snd_rawmidi,snd_hwdep,snd_usbmidi_lib,snd_usb_audio,snd_bcm2835
videobuf2_vmalloc 1965 1 stk1160
videobuf2_memops 2372 1 videobuf2_vmalloc
videobuf2_core 21234 1 stk1160
v4l2_common 9351 2 stk1160,saa7115
videodev 89925 3 v4l2_common,stk1160,saa7115
root@raspberrypi:/home/pi#

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

compiler errors/warnings if any

root@raspberrypi:/home/pi# cd stk
root@raspberrypi:/home/pi/stk# make
make -C /lib/modules/3.2.27-g10182a3/build M=/home/pi/stk modules
make[1]: Wej¶cie do katalogu /usr/src/linux' CC [M] /home/pi/stk/stk1160-core.o CC [M] /home/pi/stk/stk1160-v4l.o CC [M] /home/pi/stk/stk1160-video.o CC [M] /home/pi/stk/stk1160-i2c.o LD [M] /home/pi/stk/stk1160.o Building modules, stage 2. MODPOST 1 modules CC /home/pi/stk/stk1160.mod.o LD [M] /home/pi/stk/stk1160.ko make[1]: Opuszczenie katalogu/usr/src/linux'
root@raspberrypi:/home/pi/stk# make install
make -C /lib/modules/3.2.27-g10182a3/build M=/home/pi/stk modules_install
make[1]: Wej¶cie do katalogu /usr/src/linux' INSTALL /home/pi/stk/stk1160.ko DEPMOD 3.2.27-g10182a3 make[1]: Opuszczenie katalogu/usr/src/linux'
root@raspberrypi:/home/pi/stk#

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

MPlayer log:

root@raspberrypi:/home/pi# mplayer -msglevel all=9 tv:// -tv driver=v4l2:device=/dev/video0:input=3:norm=NTSC-M
Adding file tv://
this_opt = option: tv
Checking tv=driver=v4l2:device=/dev/video0:input=3:norm=NTSC-M
Config pushed level is now 2
Config pushed level is now 3
Setting tv=driver=v4l2:device=/dev/video0:input=3:norm=NTSC-M
MPlayer svn r34540 (Debian), built with gcc-4.6 (C) 2000-2012 MPlayer Team
CPU: ARM
get_path('codecs.conf') -> '/root/.mplayer/codecs.conf'
Reading optional codecs config file /root/.mplayer/codecs.conf: No such file or directory
Reading optional codecs config file /etc/mplayer/codecs.conf: No such file or directory
Using built-in default codecs.conf.
init_freetype
Using Unoptimized OnScreenDisplay
get_path('fonts') -> '/root/.mplayer/fonts'
Configuration: --prefix=/usr --confdir=/etc/mplayer --enable-xvmc --enable-menu --disable-arts --language=all --disable-dvdread-internal --disable-libdvdcss-internal --disable-libmpeg2-internal --disable-ffmpeg_a --enable-debug --enable-joystick --disable-gui
CommandLine: '-msglevel' 'all=9' 'tv://' '-tv' 'driver=v4l2:device=/dev/video0:input=3:norm=NTSC-M'
Using nanosleep() timing
get_path('input.conf') -> '/root/.mplayer/input.conf'
Reading optional input config file /root/.mplayer/input.conf: No such file or directory
Parsing input config file /etc/mplayer/input.conf
Input config file /etc/mplayer/input.conf parsed: 92 binds
Setting up LIRC support...
mplayer: could not connect to socket
mplayer: No such file or directory
Failed to open LIRC support. You will not be able to use your remote control.
get_path('.conf') -> '/root/.mplayer/.conf'

[[[init getch2]]]

Playing tv://.
get_path('sub/') -> '/root/.mplayer/sub/'
STREAM: [tv] tv://
STREAM: Description: TV Input
STREAM: Author: Benjamin Zores, Albeu
STREAM: Comment:
seek to 0x0
s->pos=0 newpos=0 new_bufpos=0 buflen=0
TV file format detected.
Selected driver: v4l2
name: Video 4 Linux 2 input
author: Martin Olschewski olschewski@zpr.uni-koeln.de
comment: first try, more to come ;-)
v4l2: video fd: /dev/video0: 3
Selected device: stk1160
Capabilities: video capture read/write streaming
supported norms: 0 = NTSC; 1 = NTSC-M; 2 = NTSC-M-JP; 3 = NTSC-M-KR; 4 = NTSC-443; 5 = PAL; 6 = PAL-BG; 7 = PAL-H; 8 = PAL-I; 9 = PAL-DK; 10 = PAL-M; 11 = PAL-N; 12 = PAL-Nc; 13 = PAL-60; 14 = SECAM; 15 = SECAM-B; 16 = SECAM-G; 17 = SECAM-H; 18 = SECAM-DK; 19 = SECAM-L; 20 = SECAM-Lc;
inputs: 0 = Composite0; 1 = Composite1; 2 = Composite2; 3 = Composite3;
Current input: 0
Format UYVY (16 bits, 16 bpp YUY2, 4:2:2, packed): Packed UYVY
Current format: UYVY
v4l2: set format: YVU420
v4l2: ioctl set format failed: Invalid argument
v4l2: set format: YUV420
v4l2: ioctl set format failed: Invalid argument
v4l2: set format: UYVY
v4l2: set input: 3
Selected norm : NTSC-M
v4l2: set norm: NTSC-M
Selected input hasn't got a tuner!
==> Found video stream: 0
v4l2: get format: UYVY
v4l2: get fps: 29.970030
v4l2: get width: 720
v4l2: get height: 480
Using a ring buffer for maximum 2 frames, 1 MB total size.
v4l2: ioctl set mute failed: Invalid argument
v4l2: set Brightness: 128 [0, 255]
v4l2: set Hue: 0 [-128, 127]
v4l2: set Saturation: 64 [0, 127]
v4l2: set Contrast: 64 [0, 127]
[V] filefmt:9 fourcc:0x59565955 size:720x480 fps:29.970 ftime:=0.0334
get_path('sub/') -> '/root/.mplayer/sub/'
v4l2: going to capture

fps = -1.000000, interval = 0.000000, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 26.075619, interval = 0.038350, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]
X11 opening display: :1

fps = 25.982124, interval = 0.076838, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Xlib: extension "XFree86-VidModeExtension" missing on display ":1".
vo: X11 color mask: FFFFFF (R:FF0000 G:FF00 B:FF)
vo: X11 running at 1024x768 with depth 24 and 32 bpp (":1" => local display)
[x11] Detected wm supports NetWM.
[x11] Detected wm supports FULLSCREEN state.
[x11] Detected wm supports ABOVE state.
[x11] Detected wm supports BELOW state.
[x11] Current fstype setting honours FULLSCREEN ABOVE BELOW X atoms
Xlib: extension "XVideo" missing on display ":1".
[VO_XV] Sorry, Xv not supported by this X11 version/driver
[VO_XV] ******** Try with -vo x11 or -vo sdl *********

[gl] no GLX support present

Opening video decoder: [raw] RAW Uncompressed Video
VDec: vo config request - 720 x 480 (preferred colorspace: Packed UYVY)
Trying filter chain: vo
vo_x11: query_format was called: 59565955 (Packed UYVY)
vo_debug: query(Packed UYVY) returned 0x0 (i=0)
Could not find matching colorspace - retrying with -vf scale...
Opening video filter: [scale]
SwScale params: -1 x -1 (-1=no scaling)
Trying filter chain: scale vo
vo_x11: query_format was called: 59565955 (Packed UYVY)
scale: query(Packed UYVY) -> 0
vo_x11: query_format was called: 32595559 (Packed YUY2)
scale: query(Packed YUY2) -> 0
vo_x11: query_format was called: 50323234 (Planar 422P)
scale: query(Planar 422P) -> 0
vo_x11: query_format was called: 50343434 (Planar 444P)
scale: query(Planar 444P) -> 0
vo_x11: query_format was called: 51343434 (Planar 444P 16-bit little-endian)
scale: query(Planar 444P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34343451 (Planar 444P 16-bit big-endian)
scale: query(Planar 444P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52343434 (Planar 444P 10-bit little-endian)
scale: query(Planar 444P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34343452 (Planar 444P 10-bit big-endian)
scale: query(Planar 444P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53343434 (Planar 444P 9-bit little-endian)
scale: query(Planar 444P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34343453 (Planar 444P 9-bit big-endian)
scale: query(Planar 444P 9-bit big-endian) -> 0
vo_x11: query_format was called: 50323234 (Planar 422P)
scale: query(Planar 422P) -> 0
vo_x11: query_format was called: 51323234 (Planar 422P 16-bit little-endian)
scale: query(Planar 422P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34323251 (Planar 422P 16-bit big-endian)
scale: query(Planar 422P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52323234 (Planar 422P 10-bit little-endian)
scale: query(Planar 422P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34323252 (Planar 422P 10-bit big-endian)
scale: query(Planar 422P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53323234 (Planar 422P 9-bit little-endian)
scale: query(Planar 422P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34323253 (Planar 422P 9-bit big-endian)
scale: query(Planar 422P 9-bit big-endian) -> 0
vo_x11: query_format was called: 32315659 (Planar YV12)
scale: query(Planar YV12) -> 1
vo_x11: query_format was called: 30323449 (Planar I420)
scale: query(Planar I420) -> 1
vo_x11: query_format was called: 51303234 (Planar 420P 16-bit little-endian)
scale: query(Planar 420P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34323051 (Planar 420P 16-bit big-endian)
scale: query(Planar 420P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52303234 (Planar 420P 10-bit little-endian)
scale: query(Planar 420P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34323052 (Planar 420P 10-bit big-endian)
scale: query(Planar 420P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53303234 (Planar 420P 9-bit little-endian)
scale: query(Planar 420P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34323053 (Planar 420P 9-bit big-endian)
scale: query(Planar 420P 9-bit big-endian) -> 0
vo_x11: query_format was called: 41303234 (Planar 420P with alpha)
scale: query(Planar 420P with alpha) -> 0
vo_x11: query_format was called: 56555949 (Planar IYUV)
scale: query(Planar IYUV) -> 1
vo_x11: query_format was called: 39555659 (Planar YVU9)
scale: query(Planar YVU9) -> 0
vo_x11: query_format was called: 39304649 (Planar IF09)
scale: query(Planar IF09) -> 0
vo_x11: query_format was called: 50313134 (Planar 411P)
scale: query(Planar 411P) -> 0
vo_x11: query_format was called: 3231564e (Planar NV12)
scale: query(Planar NV12) -> 0
vo_x11: query_format was called: 3132564e (Planar NV21)
scale: query(Planar NV21) -> 0
vo_x11: query_format was called: 32595559 (Packed YUY2)
scale: query(Packed YUY2) -> 0
vo_x11: query_format was called: 59565955 (Packed UYVY)
scale: query(Packed UYVY) -> 0
vo_x11: query_format was called: 50303434 (Unknown 0x50303434)
scale: query(Unknown 0x50303434) -> 0
vo_x11: query_format was called: 42475220 (BGRA)
scale: query(BGRA) -> 3
vo_x11: query_format was called: 42475220 (BGRA)
vo_debug: query(Packed UYVY) returned 0x4C5 (i=0)
VDec: using Packed UYVY as output csp (no 0)
Movie-Aspect is undefined - no prescaling applied.
VO Config (720x480->720x480,flags=0,'MPlayer',0x59565955)
vo_x11: query_format was called: 59565955 (Packed UYVY)
scale: query(Packed UYVY) -> 0
vo_x11: query_format was called: 32595559 (Packed YUY2)
scale: query(Packed YUY2) -> 0
vo_x11: query_format was called: 50323234 (Planar 422P)
scale: query(Planar 422P) -> 0
vo_x11: query_format was called: 50343434 (Planar 444P)
scale: query(Planar 444P) -> 0
vo_x11: query_format was called: 51343434 (Planar 444P 16-bit little-endian)
scale: query(Planar 444P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34343451 (Planar 444P 16-bit big-endian)
scale: query(Planar 444P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52343434 (Planar 444P 10-bit little-endian)
scale: query(Planar 444P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34343452 (Planar 444P 10-bit big-endian)
scale: query(Planar 444P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53343434 (Planar 444P 9-bit little-endian)
scale: query(Planar 444P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34343453 (Planar 444P 9-bit big-endian)
scale: query(Planar 444P 9-bit big-endian) -> 0
vo_x11: query_format was called: 50323234 (Planar 422P)
scale: query(Planar 422P) -> 0
vo_x11: query_format was called: 51323234 (Planar 422P 16-bit little-endian)
scale: query(Planar 422P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34323251 (Planar 422P 16-bit big-endian)
scale: query(Planar 422P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52323234 (Planar 422P 10-bit little-endian)
scale: query(Planar 422P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34323252 (Planar 422P 10-bit big-endian)
scale: query(Planar 422P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53323234 (Planar 422P 9-bit little-endian)
scale: query(Planar 422P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34323253 (Planar 422P 9-bit big-endian)
scale: query(Planar 422P 9-bit big-endian) -> 0
vo_x11: query_format was called: 32315659 (Planar YV12)
scale: query(Planar YV12) -> 1
vo_x11: query_format was called: 30323449 (Planar I420)
scale: query(Planar I420) -> 1
vo_x11: query_format was called: 51303234 (Planar 420P 16-bit little-endian)
scale: query(Planar 420P 16-bit little-endian) -> 0
vo_x11: query_format was called: 34323051 (Planar 420P 16-bit big-endian)
scale: query(Planar 420P 16-bit big-endian) -> 0
vo_x11: query_format was called: 52303234 (Planar 420P 10-bit little-endian)
scale: query(Planar 420P 10-bit little-endian) -> 0
vo_x11: query_format was called: 34323052 (Planar 420P 10-bit big-endian)
scale: query(Planar 420P 10-bit big-endian) -> 0
vo_x11: query_format was called: 53303234 (Planar 420P 9-bit little-endian)
scale: query(Planar 420P 9-bit little-endian) -> 0
vo_x11: query_format was called: 34323053 (Planar 420P 9-bit big-endian)
scale: query(Planar 420P 9-bit big-endian) -> 0
vo_x11: query_format was called: 41303234 (Planar 420P with alpha)
scale: query(Planar 420P with alpha) -> 0
vo_x11: query_format was called: 56555949 (Planar IYUV)
scale: query(Planar IYUV) -> 1
vo_x11: query_format was called: 39555659 (Planar YVU9)
scale: query(Planar YVU9) -> 0
vo_x11: query_format was called: 39304649 (Planar IF09)
scale: query(Planar IF09) -> 0
vo_x11: query_format was called: 50313134 (Planar 411P)
scale: query(Planar 411P) -> 0
vo_x11: query_format was called: 3231564e (Planar NV12)
scale: query(Planar NV12) -> 0
vo_x11: query_format was called: 3132564e (Planar NV21)
scale: query(Planar NV21) -> 0
vo_x11: query_format was called: 32595559 (Packed YUY2)
scale: query(Packed YUY2) -> 0
vo_x11: query_format was called: 59565955 (Packed UYVY)
scale: query(Packed UYVY) -> 0
vo_x11: query_format was called: 50303434 (Unknown 0x50303434)
scale: query(Unknown 0x50303434) -> 0
vo_x11: query_format was called: 42475220 (BGRA)
scale: query(BGRA) -> 3
vo_x11: query_format was called: 42475220 (BGRA)
SwScale: scaling 720x480 Packed UYVY to 720x480 BGRA
[swscaler @ 0x1456320] BICUBIC scaler, from uyvy422 to bgra using C
vo_x11: query_format was called: 42475220 (BGRA)
REQ: flags=0x4C7 req=0x0
VO: [x11] 720x480 => 720x480 BGRA
VO: Description: X11 ( XImage/Shm )
VO: Author: Aaron Holtzman aholtzma@ess.engr.uvic.ca
vo_x11: query_format was called: 42475220 (BGRA)
Sharing memory.
[swscaler @ 0x14691a0] using unscaled bgra -> bgra special converter

Selected video codec: [rawuyvy] vfm: raw (RAW UYVY)

Audio: no sound
Freeing 0 unused audio chunks.
Starting playback...
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=566370 pts=0.000 pos=0 [packs: A=0 V=1]
*** [scale] Exporting mp_image_t, 720x480x16bpp YUV packed, 691200 bytes
(imgfmt: 59565955, planes: (nil),(nil),(nil) strides: 0,0,0, chroma: 0x0, shift: h:1,v:0)

fps = 25.791809, interval = 0.115610, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** [vo] Allocating mp_image_t, 720x480x32bpp BGR packed, 1382400 bytes
(imgfmt: 42475220, planes: 0x444e1020,(nil),(nil) strides: 2880,0,0, chroma: 0x0, shift: h:0,v:0)
Unicode font: 5179 glyphs.
Unicode font: 5179 glyphs.
OSD chg: 6 V: no pb:-1
OSD chg: 5 V: no pb:-1
OSD chg: 3 V: no pb:-1
OSD chg: 2 V: no pb:-1
*** ftime=0.000 ***
V: 0.0 1/ 1 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=576572 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (566370<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 2/ 2 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 21.176122, interval = 0.162833, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=609856 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (576572<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 3/ 3 ??% ??% ??,?% 0 0

fps = 25.079628, interval = 0.202706, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=623300 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (609856<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 4/ 4 ??% ??% ??,?% 0 0

fps = 31.036623, interval = 0.234926, a_skew = 0.000000, corr_skew = 0.000000

vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=607414 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (623300<691200) Wrong format?

fps = 20.867678, interval = 0.282847, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 5/ 5 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=609764 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.071454, interval = 0.322733, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (607414<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 6/ 6 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=609290 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (609764<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 7/ 7 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 24.994376, interval = 0.362742, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.319661, interval = 0.402237, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=609462 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (609290<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 8/ 8 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0

fps = 1.397866, interval = 1.117613, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=608532 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (609462<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 9/ 9 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0

fps = 0.609801, interval = 2.757492, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=597746 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (608532<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 10/ 10 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0

fps = 25.314533, interval = 2.796995, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=575050 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (597746<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 11/ 11 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=566366 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (575050<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 12/ 12 ??% ??% ??,?% 0 0

fps = 12.173003, interval = 2.879144, a_skew = 0.000000, corr_skew = 0.000000

vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=577856 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (566366<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 13/ 13 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.754610, interval = 2.917972, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=528562 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.599017, interval = 2.957036, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (577856<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 14/ 14 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=541174 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.079628, interval = 2.996909, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (528562<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 15/ 15 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=569136 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.865725, interval = 3.037125, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (541174<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 16/ 16 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=579964 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (569136<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 17/ 17 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.310048, interval = 3.076635, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=561906 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (579964<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 18/ 18 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 24.839783, interval = 3.116893, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 24.782533, interval = 3.157244, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=587758 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (561906<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 19/ 19 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=582334 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.242964, interval = 3.196859, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (587758<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 20/ 20 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=580240 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.509553, interval = 3.236060, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (582334<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 21/ 21 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=590900 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.662082, interval = 3.275028, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (580240<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 22/ 22 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=606648 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 21.274785, interval = 3.322032, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (590900<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 23/ 23 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=618594 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.152171, interval = 3.361790, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (606648<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 24/ 24 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=615204 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (618594<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 25/ 25 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=575720 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (615204<691200) Wrong format?
*** ftime=0.000 ***

fps = 25.392311, interval = 3.401172, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 25.454360, interval = 3.440458, a_skew = 0.000000, corr_skew = 0.000000
V: 0.0 26/ 26 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=562424 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0
Frame too small! (575720<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 27/ 27 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=542454 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.900026, interval = 3.479068, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 26.143107, interval = 3.517319, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (562424<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 28/ 28 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=553120 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0
Frame too small! (542454<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 29/ 29 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.678556, interval = 3.556262, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.572831, interval = 3.595366, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (553120<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 30/ 30 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0

fps = 25.128785, interval = 3.635161, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=603258 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 31/ 31 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=614454 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (603258<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 32/ 32 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 20.866807, interval = 3.683084, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=616494 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.700995, interval = 3.721993, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (614454<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 33/ 33 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=617460 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.229589, interval = 3.761629, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (616494<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 34/ 34 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=614966 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.311329, interval = 3.801137, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (617460<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 35/ 35 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=574692 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (614966<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 36/ 36 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.520621, interval = 3.840321, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 26.080380, interval = 3.878664, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=559176 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (574692<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 37/ 37 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=544260 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (559176<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 38/ 38 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.704958, interval = 3.917567, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (544260<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 39/ 39 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.761908, interval = 3.956384, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=558260 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 4.917533, interval = 4.159738, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 40/ 40 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=594640 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (558260<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 41/ 41 ??% ??% ??,?% 0 0

fps = 25.006252, interval = 4.199728, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=524700 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.003125, interval = 4.239723, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (594640<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 42/ 42 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=522930 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.405213, interval = 4.279085, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (524700<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 43/ 43 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 12.095116, interval = 4.361763, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (522930<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 44/ 44 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=533884 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (517668<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 45/ 45 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 24.300746, interval = 4.402914, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 30.882308, interval = 4.435295, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=543006 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (533884<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 46/ 46 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=566528 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (543006<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 47/ 47 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.187648, interval = 4.474997, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=603224 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (566528<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 48/ 48 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=603088 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.013132, interval = 4.514976, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 3.103845, interval = 4.837157, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (603224<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 49/ 49 ??% ??% ??,?% 0 0

vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=613654 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.097252, interval = 4.877002, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (603088<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 50/ 50 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=575666 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (613654<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 51/ 51 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.048218, interval = 4.916925, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=585836 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (575666<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 52/ 52 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.249337, interval = 4.956530, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.531046, interval = 4.995698, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (585836<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 53/ 53 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=592390 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.320302, interval = 5.035192, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 54/ 54 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=609600 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.816975, interval = 5.075487, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (592390<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 55/ 55 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=612662 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.823135, interval = 5.115772, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (609600<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 56/ 56 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=595956 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.085919, interval = 5.155635, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (612662<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 57/ 57 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=599954 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.802818, interval = 5.195953, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (595956<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 58/ 58 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=603038 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.431360, interval = 5.236884, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (599954<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 59/ 59 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=590576 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.219409, interval = 5.276536, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (603038<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 60/ 60 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=573206 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.182574, interval = 5.316246, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (590576<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 61/ 61 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=596256 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (573206<691200) Wrong format?

fps = 24.867580, interval = 5.356459, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 62/ 62 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=593484 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 3.501903, interval = 5.642018, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (596256<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 63/ 63 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=575904 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.599036, interval = 5.682670, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (593484<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 64/ 64 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=565198 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (575904<691200) Wrong format?
*** ftime=0.000 ***

fps = 30.817591, interval = 5.715119, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
V: 0.0 65/ 65 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=585956 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.685263, interval = 5.755629, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (565198<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 66/ 66 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=611644 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (585956<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 67/ 67 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.087807, interval = 5.795489, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 24.778849, interval = 5.835846, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=593812 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (611644<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 68/ 68 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=606914 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (593812<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 69/ 69 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=591346 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.799742, interval = 5.876169, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 25.338908, interval = 5.915634, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (606914<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 70/ 70 ??% ??% ??,?% 0 0
vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=590008 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (591346<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 71/ 71 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.162930, interval = 5.955375, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=607916 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (590008<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 72/ 72 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=600156 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.925224, interval = 5.995495, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0

fps = 24.919013, interval = 6.035625, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (607916<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 73/ 73 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=602630 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 24.879954, interval = 6.075818, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (600156<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 74/ 74 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=604090 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 24.942010, interval = 6.115911, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (602630<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 75/ 75 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=600734 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 25.078999, interval = 6.155785, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (604090<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 76/ 76 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=599372 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0
Frame too small! (600734<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 77/ 77 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=596976 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.078370, interval = 6.195660, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 0, acnt = 0
Frame too small! (599372<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 78/ 78 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.264647, interval = 6.235241, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 21.167157, interval = 6.282484, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=601460 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (596976<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 79/ 79 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0

fps = 25.513458, interval = 6.321679, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=612126 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (601460<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 80/ 80 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=620206 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (612126<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 81/ 81 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.138260, interval = 6.361459, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.405213, interval = 6.400821, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=587978 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (620206<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 82/ 82 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=567540 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (587978<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 83/ 83 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.531698, interval = 6.439988, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 12.529601, interval = 6.519799, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (567540<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 84/ 84 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=549054 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.847140, interval = 6.558488, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 85/ 85 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=552650 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 26.039632, interval = 6.596891, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (549054<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 86/ 86 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=552844 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.676578, interval = 6.635837, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (552650<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 87/ 87 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=574464 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.333131, interval = 6.675311, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (552844<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 88/ 88 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 21.234127, interval = 6.722405, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=605920 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (574464<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 89/ 89 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=610186 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (605920<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 90/ 90 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 24.992502, interval = 6.762417, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.550616, interval = 6.801555, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=616628 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (610186<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 91/ 91 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=598480 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 25.390377, interval = 6.840940, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (616628<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 92/ 92 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=585222 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 25.776518, interval = 6.879735, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (598480<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 93/ 93 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=554240 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 4.242411, interval = 7.115450, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (585222<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 94/ 94 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=550856 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.047590, interval = 7.155374, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (554240<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 95/ 95 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=602824 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 24.747575, interval = 7.195782, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (550856<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 96/ 96 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=595934 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 12.230471, interval = 7.277545, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (602824<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 97/ 97 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=592830 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (595934<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 98/ 98 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.173065, interval = 7.317270, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0

fps = 25.372983, interval = 7.356682, a_skew = 0.000000, corr_skew = 0.000000
DEMUX: Append packet to d_video, len=558658 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (592830<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 99/ 99 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=563646 pts=0.000 pos=0 [packs: A=0 V=1]
vcnt = 0, acnt = 0

fps = 24.915909, interval = 7.396817, a_skew = 0.000000, corr_skew = 0.000000
Frame too small! (558658<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 100/100 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=592308 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (563646<691200) Wrong format?

fps = 24.906600, interval = 7.436967, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 101/101 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=573922 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.106073, interval = 7.476798, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (592308<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 102/102 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=584362 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.239141, interval = 7.516419, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (573922<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 103/103 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 24.860162, interval = 7.556644, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=578540 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (584362<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 104/104 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=596878 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (578540<691200) Wrong format?

fps = 24.635396, interval = 7.597236, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 105/105 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=576916 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (596878<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 106/106 ??% ??% ??,?% 0 0

fps = 25.641026, interval = 7.636236, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=570138 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (576916<691200) Wrong format?

fps = 25.055749, interval = 7.676147, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 107/107 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=592048 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (570138<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 108/108 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.348542, interval = 7.715597, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=596960 pts=0.000 pos=0 [packs: A=0 V=1]
Frame too small! (592048<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 109/109 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called

fps = 25.079628, interval = 7.755470, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
DEMUX: Append packet to d_video, len=691200 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 21.141649, interval = 7.802770, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
Frame too small! (596960<691200) Wrong format?
*** ftime=0.000 ***
V: 0.0 110/110 ??% ??% ??,?% 0 0
ds_fill_buffer(d_video) called
DEMUX: Append packet to d_video, len=596070 pts=0.000 pos=0 [packs: A=0 V=1]

fps = 25.388443, interval = 7.842158, a_skew = 0.000000, corr_skew = 0.000000
vcnt = 1, acnt = 0
*** ftime=0.000 ***
V: 0.0 111/111 ??% ??% ??,?% 0 0

*** uninit(0x1AC9)
Uninit video: raw
DEMUXER: freeing TV demuxer at 0x144ada0
v4l2: ioctl set mute failed: Invalid argument
v4l2: 114 frames successfully processed, 122 frames dropped.
v4l2: up to 2 video frames buffered.
DEMUXER: freeing sh_video at 0x143d6b0

[[[uninit getch2]]]
vo: uninit ...

Exiting... (Quit)
max framesize was 691200 bytes
root@raspberrypi:/home/pi#

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

dmesg after mplayer running

root@raspberrypi:/home/pi#
root@raspberrypi:/home/pi# dmesg
[ 0.000000] Initializing cgroup subsys cpuset
[ 0.000000] Initializing cgroup subsys cpu
[ 0.000000] Linux version 3.2.27-g10182a3 (root@raspberrypi) (gcc version 4.6.3 (Debian 4.6.3-8+rpi1) ) #1 PREEMPT Tue Oct 16 23:53:52 CEST 2012
[ 0.000000] CPU: ARMv6-compatible processor [410fb767] revision 7 (ARMv7), cr=00c5387d
[ 0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT nonaliasing instruction cache
[ 0.000000] Machine: BCM2708
[ 0.000000] Memory policy: ECC disabled, Data cache writeback
[ 0.000000] On node 0 totalpages: 32768
[ 0.000000] free_area_init_node: node 0, pgdat c055d5a0, node_mem_map c060c000
[ 0.000000] Normal zone: 256 pages used for memmap
[ 0.000000] Normal zone: 0 pages reserved
[ 0.000000] Normal zone: 32512 pages, LIFO batch:7
[ 0.000000] pcpu-alloc: s0 r0 d32768 u32768 alloc=1*32768
[ 0.000000] pcpu-alloc: [0] 0
[ 0.000000] Built 1 zonelists in Zone order, mobility grouping on. Total pages: 32512
[ 0.000000] Kernel command line: dma.dmachans=0x7f35 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708.boardrev=0x4 bcm2708.serial=0xea3a3961 smsc95xx.macaddr=B8:27:EB:3A:39:61 dwc_otg.lpm_enable=0 console=ttyAMA0,115200 kgdboc=ttyAMA0,115200 console=tty1 root=/dev/mmcblk0p2 rootfstype=ext4 elevator=deadline rootwait
[ 0.000000] PID hash table entries: 512 (order: -1, 2048 bytes)
[ 0.000000] Dentry cache hash table entries: 16384 (order: 4, 65536 bytes)
[ 0.000000] Inode-cache hash table entries: 8192 (order: 3, 32768 bytes)
[ 0.000000] Memory: 128MB = 128MB total
[ 0.000000] Memory: 123704k/123704k available, 7368k reserved, 0K highmem
[ 0.000000] Virtual kernel memory layout:
[ 0.000000] vector : 0xffff0000 - 0xffff1000 ( 4 kB)
[ 0.000000] fixmap : 0xfff00000 - 0xfffe0000 ( 896 kB)
[ 0.000000] vmalloc : 0xc8800000 - 0xe8000000 ( 504 MB)
[ 0.000000] lowmem : 0xc0000000 - 0xc8000000 ( 128 MB)
[ 0.000000] pkmap : 0xbfe00000 - 0xc0000000 ( 2 MB)
[ 0.000000] modules : 0xbf000000 - 0xbfe00000 ( 14 MB)
[ 0.000000] .text : 0xc0008000 - 0xc050bae4 (5135 kB)
[ 0.000000] .init : 0xc050c000 - 0xc052ff4c ( 144 kB)
[ 0.000000] .data : 0xc0530000 - 0xc055df20 ( 184 kB)
[ 0.000000] .bss : 0xc055df44 - 0xc060b3a8 ( 694 kB)
[ 0.000000] NR_IRQS:330
[ 0.000000] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 4294967ms
[ 0.000000] timer_set_mode: unhandled mode:1
[ 0.000000] timer_set_mode: unhandled mode:3
[ 0.000000] Console: colour dummy device 80x30
[ 0.000000] console [tty1] enabled
[ 0.000955] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
[ 0.060156] pid_max: default: 32768 minimum: 301
[ 0.060657] Mount-cache hash table entries: 512
[ 0.061174] Initializing cgroup subsys cpuacct
[ 0.061266] Initializing cgroup subsys devices
[ 0.061302] Initializing cgroup subsys freezer
[ 0.061333] Initializing cgroup subsys blkio
[ 0.061482] CPU: Testing write buffer coherency: ok
[ 0.061830] hw perfevents: enabled with v6 PMU driver, 3 counters available
[ 0.063323] devtmpfs: initialized
[ 0.073692] NET: Registered protocol family 16
[ 0.074434] i2c-core: driver [dummy] registered
[ 0.074454] bcm2708.uart_clock = 0
[ 0.076949] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[ 0.077010] hw-breakpoint: maximum watchpoint size is 4 bytes.
[ 0.077049] mailbox: Broadcom VideoCore Mailbox driver
[ 0.077150] bcm2708_vcio: mailbox at f200b880
[ 0.077265] bcm_power: Broadcom power driver
[ 0.077304] bcm_power_open() -> 0
[ 0.077330] bcm_power_request(0, 8)
[ 0.578009] bcm_mailbox_read -> 00000080, 0
[ 0.578050] bcm_power_request -> 0
[ 0.578272] Serial: AMBA PL011 UART driver
[ 0.578441] dev:f1: ttyAMA0 at MMIO 0x20201000 (irq = 83) is a PL011 rev3
[ 0.885607] console [ttyAMA0] enabled
[ 0.912323] bio: create slab at 0
[ 0.917674] SCSI subsystem initialized
[ 0.921677] usbcore: registered new interface driver usbfs
[ 0.927452] usbcore: registered new interface driver hub
[ 0.933055] usbcore: registered new device driver usb
[ 0.941232] DMA-API: preallocated 4096 debug entries
[ 0.946253] DMA-API: debugging enabled by kernel config
[ 0.951596] Switching to clocksource stc
[ 0.955862] FS-Cache: Loaded
[ 0.959158] CacheFiles: Loaded
[ 0.980293] NET: Registered protocol family 2
[ 0.985140] IP route cache hash table entries: 1024 (order: 0, 4096 bytes)
[ 0.993314] TCP established hash table entries: 4096 (order: 3, 32768 bytes)
[ 1.000651] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[ 1.007236] TCP: Hash tables configured (established 4096 bind 4096)
[ 1.013609] TCP reno registered
[ 1.016802] UDP hash table entries: 256 (order: 0, 4096 bytes)
[ 1.022683] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[ 1.029543] NET: Registered protocol family 1
[ 1.034689] RPC: Registered named UNIX socket transport module.
[ 1.040833] RPC: Registered udp transport module.
[ 1.045594] RPC: Registered tcp transport module.
[ 1.050315] RPC: Registered tcp NFSv4.1 backchannel transport module.
[ 1.057091] NetWinder Floating Point Emulator V0.97 (extended precision)
[ 1.064005] bcm2708_dma: DMA manager at c8808000
[ 1.068853] bcm2708_gpio: bcm2708_gpio_probe c0537dd8
[ 1.074330] vc-mem: phys_addr:0x00000000 mem_base=0x00000000 mem_size:0x00000000(0 MiB)
[ 1.083617] audit: initializing netlink socket (disabled)
[ 1.089251] type=2000 audit(0.770:1): initialized
[ 1.214024] VFS: Disk quotas dquot_6.5.2
[ 1.218291] Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[ 1.225962] FS-Cache: Netfs 'nfs' registered for caching
[ 1.232308] msgmni has been set to 241
[ 1.238264] io scheduler noop registered
[ 1.242233] io scheduler deadline registered (default)
[ 1.247722] io scheduler cfq registered
[ 1.270466] Console: switching to colour frame buffer device 82x26
[ 1.282948] uart-pl011 dev:f1: no DMA platform data
[ 1.290100] kgdb: Registered I/O driver kgdboc.
[ 1.308238] brd: module loaded
[ 1.319649] loop: module loaded
[ 1.326072] vcos: [1]: vchiq_init_state: slot_zero = 0xffd80000, is_master = 0
[ 1.336271] vcos: [1]: vchiq_init_state: called
[ 1.344021] vcos: [1]: vchiq: initialised - version 2 (min 2), device 252.0
[ 1.354025] usbcore: registered new interface driver smsc95xx
[ 1.362182] cdc_ncm: 04-Aug-2011
[ 1.367803] usbcore: registered new interface driver cdc_ncm
[ 1.375694] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[ 1.588760] Core Release: 2.80a
[ 1.594048] Setting default values for core params
[ 1.601127] Finished setting default values for core params
[ 1.814011] Using Buffer DMA mode
[ 1.819485] Periodic Transfer Interrupt Enhancement - disabled
[ 1.827501] Multiprocessor Interrupt Enhancement - disabled
[ 1.835228] OTG VER PARAM: 0, OTG VER FLAG: 0
[ 1.841773] Dedicated Tx FIFOs mode
[ 1.847875] dwc_otg: Microframe scheduler enabled
[ 1.847930] dwc_otg bcm2708_usb: DWC OTG Controller
[ 1.855083] drivers/usb/core/inode.c: creating file 'devices'
[ 1.855173] drivers/usb/core/inode.c: creating file '001'
[ 1.855207] dwc_otg bcm2708_usb: new USB bus registered, assigned bus number 1
[ 1.864795] dwc_otg bcm2708_usb: irq 32, io mem 0x00000000
[ 1.872577] Init: Port Power? op_state=1
[ 1.878731] Init: Power Port (0)
[ 1.884195] usb usb1: default language 0x0409
[ 1.884250] usb usb1: udev 1, busnum 1, minor = 0
[ 1.884269] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[ 1.893306] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[ 1.902800] usb usb1: Product: DWC OTG Controller
[ 1.909742] usb usb1: Manufacturer: Linux 3.2.27-g10182a3 dwc_otg_hcd
[ 1.918456] usb usb1: SerialNumber: bcm2708_usb
[ 1.925955] usb usb1: usb_probe_device
[ 1.925986] usb usb1: configuration #1 chosen from 1 choice
[ 1.926058] usb usb1: adding 1-0:1.0 (config #1, interface 0)
[ 1.926279] hub 1-0:1.0: usb_probe_interface
[ 1.926299] hub 1-0:1.0: usb_probe_interface - got id
[ 1.926321] hub 1-0:1.0: USB hub found
[ 1.932274] hub 1-0:1.0: 1 port detected
[ 1.938394] hub 1-0:1.0: standalone hub
[ 1.938421] hub 1-0:1.0: ganged power switching
[ 1.938435] hub 1-0:1.0: individual port over-current protection
[ 1.938449] hub 1-0:1.0: Single TT
[ 1.938465] hub 1-0:1.0: TT requires at most 8 FS bit times (666 ns)
[ 1.938481] hub 1-0:1.0: power on to power good time: 2ms
[ 1.938539] hub 1-0:1.0: local power source is good
[ 1.938559] hub 1-0:1.0: enabling power on all ports
[ 1.939094] drivers/usb/core/inode.c: creating file '001'
[ 1.939401] dwc_otg: FIQ enabled
[ 1.939415] dwc_otg: NAK holdoff enabled
[ 1.939436] Module dwc_common_port init
[ 1.939780] usbcore: registered new interface driver uas
[ 1.947379] Initializing USB Mass Storage driver...
[ 1.954598] usbcore: registered new interface driver usb-storage
[ 1.962826] USB Mass Storage support registered.
[ 1.969893] usbcore: registered new interface driver libusual
[ 1.978311] mousedev: PS/2 mouse device common for all mice
[ 1.987035] bcm2835-cpufreq: min=700000 max=700000 cur=700000
[ 1.992867] bcm2835-cpufreq: switching to governor performance
[ 2.000963] bcm2835-cpufreq: switching to governor performance
[ 2.009155] sdhci: Secure Digital Host Controller Interface driver
[ 2.019554] sdhci: Copyright(c) Pierre Ossman
[ 2.026138] sdhci: Enable low-latency mode
[ 2.032279] bcm_power_open() -> 1
[ 2.037750] hub 1-0:1.0: port 1: status 0101 change 0001
[ 2.038159] Registered led device: mmc0::
[ 2.039646] mmc0: SDHCI controller on BCM2708_Arasan [platform] using platform's DMA
[ 2.051793] mmc0: BCM2708 SDHC host at 0x20300000 DMA 2 IRQ 77
[ 2.059929] sdhci-pltfm: SDHCI platform and OF driver helper
[ 2.069232] Registered led device: led0
[ 2.069696] usbcore: registered new interface driver usbhid
[ 2.077508] usbhid: USB HID core driver
[ 2.084736] TCP cubic registered
[ 2.090298] Initializing XFRM netlink socket
[ 2.099038] NET: Registered protocol family 17
[ 2.108986] Registering the dns_resolver key type
[ 2.118181] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[ 2.137365] hub 1-0:1.0: state 7 ports 1 chg 0002 evt 0000
[ 2.137430] hub 1-0:1.0: port 1, status 0101, change 0000, 12 Mb/s
[ 2.137480] Indeed it is in host mode hprt0 = 00021501
[ 2.147643] registered taskstats version 1
[ 2.154546] drivers/rtc/hctosys.c: unable to open rtc device (rtc0)
[ 2.185815] Waiting for root device /dev/mmcblk0p2...
[ 2.207857] mmc0: new high speed SDHC card at address 1234
[ 2.226322] mmcblk0: mmc0:1234 SA04G 3.68 GiB
[ 2.247195] mmcblk0: p1 p2
[ 2.326360] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[ 2.339311] VFS: Mounted root (ext4 filesystem) on device 179:2.
[ 2.359368] devtmpfs: mounted
[ 2.365795] Freeing init memory: 140K
[ 2.375770] usb 1-1: new high-speed USB device number 2 using dwc_otg
[ 2.384798] Indeed it is in host mode hprt0 = 00001101
[ 2.596124] usb 1-1: udev 2, busnum 1, minor = 1
[ 2.596152] usb 1-1: New USB device found, idVendor=0424, idProduct=9512
[ 2.606294] usb 1-1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 2.617380] usb 1-1: usb_probe_device
[ 2.617412] usb 1-1: configuration #1 chosen from 1 choice
[ 2.617672] usb 1-1: adding 1-1:1.0 (config #1, interface 0)
[ 2.617932] hub 1-1:1.0: usb_probe_interface
[ 2.617952] hub 1-1:1.0: usb_probe_interface - got id
[ 2.617974] hub 1-1:1.0: USB hub found
[ 2.624385] hub 1-1:1.0: 3 ports detected
[ 2.630927] hub 1-1:1.0: compound device; port removable status: FRR
[ 2.630955] hub 1-1:1.0: individual port power switching
[ 2.630969] hub 1-1:1.0: individual port over-current protection
[ 2.632403] hub 1-1:1.0: TT per port
[ 2.632432] hub 1-1:1.0: TT requires at most 8 FS bit times (666 ns)
[ 2.632449] hub 1-1:1.0: power on to power good time: 100ms
[ 2.632713] hub 1-1:1.0: local power source is good
[ 2.632753] hub 1-1:1.0: enabling power on all ports
[ 2.633425] drivers/usb/core/inode.c: creating file '002'
[ 2.633655] hub 1-0:1.0: state 7 ports 1 chg 0000 evt 0002
[ 2.633706] hub 1-0:1.0: port 1 enable change, status 00000503
[ 2.725896] hub 1-1:1.0: port 1: status 0101 change 0001
[ 2.726229] hub 1-1:1.0: port 3: status 0101 change 0001
[ 2.825871] hub 1-1:1.0: state 7 ports 3 chg 000a evt 0000
[ 2.826183] hub 1-1:1.0: port 1, status 0101, change 0000, 12 Mb/s
[ 2.906046] usb 1-1.1: new high-speed USB device number 3 using dwc_otg
[ 3.016431] usb 1-1.1: udev 3, busnum 1, minor = 2
[ 3.016459] usb 1-1.1: New USB device found, idVendor=0424, idProduct=ec00
[ 3.028381] usb 1-1.1: New USB device strings: Mfr=0, Product=0, SerialNumber=0
[ 3.039621] usb 1-1.1: usb_probe_device
[ 3.039651] usb 1-1.1: configuration #1 chosen from 1 choice
[ 3.042043] usb 1-1.1: adding 1-1.1:1.0 (config #1, interface 0)
[ 3.044238] smsc95xx 1-1.1:1.0: usb_probe_interface
[ 3.044264] smsc95xx 1-1.1:1.0: usb_probe_interface - got id
[ 3.044353] smsc95xx v1.0.4
[ 3.124626] smsc95xx 1-1.1:1.0: eth0: register 'smsc95xx' at usb-bcm2708_usb-1.1, smsc95xx USB 2.0 Ethernet, b8:27:eb:3a:39:61
[ 3.146887] drivers/usb/core/inode.c: creating file '003'
[ 3.147355] hub 1-1:1.0: port 3, status 0101, change 0000, 12 Mb/s
[ 3.225960] usb 1-1.3: new high-speed USB device number 4 using dwc_otg
[ 3.347532] usb 1-1.3: default language 0x0409
[ 3.348034] usb 1-1.3: udev 4, busnum 1, minor = 3
[ 3.348055] usb 1-1.3: New USB device found, idVendor=05e3, idProduct=0608
[ 3.358111] usb 1-1.3: New USB device strings: Mfr=0, Product=1, SerialNumber=0
[ 3.368087] usb 1-1.3: Product: USB2.0 Hub
[ 3.376153] usb 1-1.3: usb_probe_device
[ 3.376185] usb 1-1.3: configuration #1 chosen from 1 choice
[ 3.376722] usb 1-1.3: adding 1-1.3:1.0 (config #1, interface 0)
[ 3.377786] hub 1-1.3:1.0: usb_probe_interface
[ 3.377809] hub 1-1.3:1.0: usb_probe_interface - got id
[ 3.377833] hub 1-1.3:1.0: USB hub found
[ 3.384761] hub 1-1.3:1.0: 4 ports detected
[ 3.391438] hub 1-1.3:1.0: standalone hub
[ 3.391466] hub 1-1.3:1.0: individual port power switching
[ 3.391481] hub 1-1.3:1.0: individual port over-current protection
[ 3.391496] hub 1-1.3:1.0: Single TT
[ 3.391511] hub 1-1.3:1.0: TT requires at most 32 FS bit times (2664 ns)
[ 3.391525] hub 1-1.3:1.0: Port indicators are supported
[ 3.391539] hub 1-1.3:1.0: power on to power good time: 100ms
[ 3.392376] hub 1-1.3:1.0: local power source is good
[ 3.392405] hub 1-1.3:1.0: enabling power on all ports
[ 3.398559] drivers/usb/core/inode.c: creating file '004'
[ 3.496219] hub 1-1.3:1.0: port 1: status 0101 change 0001
[ 3.595844] hub 1-1.3:1.0: state 7 ports 4 chg 0002 evt 0000
[ 3.596334] hub 1-1.3:1.0: port 1, status 0101, change 0000, 12 Mb/s
[ 3.676196] usb 1-1.3.1: new high-speed USB device number 5 using dwc_otg
[ 3.796551] usb 1-1.3.1: skipped 4 descriptors after interface
[ 3.796584] usb 1-1.3.1: skipped 2 descriptors after interface
[ 3.796602] usb 1-1.3.1: skipped 1 descriptor after endpoint
[ 3.796878] usb 1-1.3.1: default language 0x0409
[ 3.797386] usb 1-1.3.1: udev 5, busnum 1, minor = 4
[ 3.797410] usb 1-1.3.1: New USB device found, idVendor=05e1, idProduct=0408
[ 3.815709] usb 1-1.3.1: New USB device strings: Mfr=1, Product=2, SerialNumber=0
[ 3.842440] usb 1-1.3.1: Product: USB 2.0 Video Capture Controller
[ 3.854470] usb 1-1.3.1: Manufacturer: Syntek Semiconductor
[ 3.864692] usb 1-1.3.1: usb_probe_device
[ 3.864725] usb 1-1.3.1: configuration #1 chosen from 1 choice
[ 3.865086] usb 1-1.3.1: adding 1-1.3.1:1.0 (config #1, interface 0)
[ 3.865857] usb 1-1.3.1: adding 1-1.3.1:1.1 (config #1, interface 1)
[ 3.866483] usb 1-1.3.1: adding 1-1.3.1:1.2 (config #1, interface 2)
[ 3.867579] drivers/usb/core/inode.c: creating file '005'
[ 4.017284] udevd[140]: starting version 175
[ 5.893744] Linux video capture interface: v2.00
[ 6.369210] stk1160 1-1.3.1:1.0: usb_probe_interface
[ 6.369241] stk1160 1-1.3.1:1.0: usb_probe_interface - got id
[ 6.369280] usb 1-1.3.1: New device Syntek Semiconductor USB 2.0 Video Capture Controller @ 480 Mbps (05e1:0408, interface 0, class 0)
[ 6.594945] usb 1-1.3.1: video interface 0 found
[ 6.685963] i2c i2c-0: adapter [stk1160] registered
[ 6.738681] i2c-core: driver [saa7115] registered
[ 6.739784] i2c i2c-0: master_xfer[0] W, addr=0x25, len=0
[ 6.740232] ------------[ cut here ]------------
[ 6.816775] WARNING: at lib/dma-debug.c:930 check_for_stack+0xac/0xfc()
[ 6.908793] dwc_otg bcm2708_usb: DMA-API: device driver maps memory fromstack [addr=c694fbc7]
[ 7.038140] Modules linked in: snd_pcm snd_page_alloc snd_seq snd_seq_device snd_timer saa7115 snd stk1160(O+) videobuf2_vmalloc videobuf2_memops videobuf2_core v4l2_common videodev
[ 7.125047] from
[ 7.215242] from
[ 7.264391] from
[ 7.302415] from
[ 7.317907] from
[ 7.334513] from
[ 7.354223] from
[ 7.370441] from
[ 7.386344] from [](stk1160_read_reg+0x4c/0x7c [stk1160])
[ 7.402862] [](stk1160_read_reg+0x4c/0x7c [stk1160]) from [](stk1160_i2c_xfer+0x1f8/0x480 [stk1160])
[ 7.420525] [](stk1160_i2c_xfer+0x1f8/0x480 [stk1160]) from
[ 7.437051] from
[ 7.452559] from
[ 7.468211] from
[ 7.484431] from [](v4l2_i2c_new_subdev_board+0x124/0x150 [v4l2_common])
[ 7.502796] [](v4l2_i2c_new_subdev_board+0x124/0x150 [v4l2_common]) from [](v4l2_i2c_new_subdev+0x5c/0x7c [v4l2_common])
[ 7.522145] [](v4l2_i2c_new_subdev+0x5c/0x7c [v4l2_common]) from [](stk1160_probe+0x34c/0x550 [stk1160])
[ 7.540096] [](stk1160_probe+0x34c/0x550 [stk1160]) from
[ 7.557268] from
[ 7.573585] from
[ 7.589441] from
[ 7.604921] from
[ 7.620486] from
[ 7.636075] from
[ 7.652156] from [](stk1160_module_init+0x14/0x40 [stk1160])
[ 7.669289] [](stk1160_module_init+0x14/0x40 [stk1160]) from
[ 7.685997] from
[ 7.701763] from
[ 7.717372] ---[ end trace eb7cb65ae68a4efd ]---
[ 7.725934] i2c 0-0025: uevent
[ 7.726471] saa7115 0-0025: probe
[ 7.726513] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.727498] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.727521] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.756123] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.756995] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.757017] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.786136] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.786999] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.787020] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.816130] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.845889] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.845911] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.876281] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.905941] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.905969] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.936023] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.965790] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.965813] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 7.996037] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 7.996901] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 7.996923] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.026030] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.055792] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.055814] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.086038] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.115811] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.115833] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.146175] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.175805] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.175828] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.206054] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.206925] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.206947] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.236047] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.265840] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.265864] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.296068] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.296941] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.296962] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.326198] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.355956] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.355980] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.386091] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.415834] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 8.415857] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 8.446084] saa7115 0-0025: saa7113 found (1f7113d0e100000) @ 0x4a (stk1160)
[ 8.456512] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.485854] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.515849] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.545851] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.546717] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.547596] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.548468] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.549343] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.575854] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.576722] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.577599] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.578472] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.605916] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.606853] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.607742] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.635896] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.665898] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.695873] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.725872] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.755876] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.756744] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.785880] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.815893] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.816750] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.817626] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.818502] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.819378] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.820252] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.845891] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.875777] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.876636] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.906067] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.935948] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.965794] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 8.995813] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.025789] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.026653] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.027527] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.028401] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.029275] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.030152] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.055796] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.056655] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.057530] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.058403] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.059281] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.060152] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.061030] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.061905] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.062782] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.063655] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.064534] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.065407] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.066408] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.067283] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.095782] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.125809] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.155829] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 9.155856] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 9.186054] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.186926] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.187798] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.215811] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.216678] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.245939] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.275839] i2c i2c-0: client [saa7113] registered with bus id 0-0025
[ 9.275892] stk1160: driver ver 0.9.3 successfully loaded
[ 9.284424] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 9.284449] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 9.306081] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.335991] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 9.336019] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 9.366075] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.368917] stk1160: registers to NTSC like standard
[ 9.370036] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.395831] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.396697] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.425833] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.455847] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.485843] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.486720] i2c i2c-0: master_xfer[0] W, addr=0x25, len=1
[ 9.486742] i2c i2c-0: master_xfer[1] R, addr=0x25, len=1
[ 9.516090] i2c i2c-0: master_xfer[0] W, addr=0x25, len=2
[ 9.517747] stk1160 1-1.3.1:1.0: V4L2 device registered as video0
[ 9.527166] snd-usb-audio 1-1.3.1:1.1: usb_probe_interface
[ 9.527249] snd-usb-audio 1-1.3.1:1.1: usb_probe_interface - got id
[ 9.532988] usbcore: registered new interface driver snd-usb-audio
[ 9.544265] usbcore: registered new interface driver stk1160
[ 9.563578] saa7115 0-0025: uevent
[ 9.564488] saa7115 0-0025: uevent
[ 9.626740] saa7115 0-0025: uevent
[ 17.286055] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 17.795867] EXT4-fs (mmcblk0p2): re-mounted. Opts: (null)
[ 18.477402] bcm2835 ALSA card created!
[ 18.483667] bcm2835 ALSA chip created!
[ 18.503390] bcm2835 ALSA chip created!
[ 18.514232] bcm2835 ALSA chip created!
[ 18.522480] bcm2835 ALSA chip created!
[ 18.530608] bcm2835 ALSA chip created!
[ 18.545033] bcm2835 ALSA chip created!
[ 18.552466] bcm2835 ALSA chip created!
[ 26.918394] smsc95xx 1-1.1:1.0: eth0: link up, 100Mbps, full-duplex, lpa 0x4DE1
[ 27.174198] bcm2835-cpufreq: switching to governor ondemand
[ 27.174227] bcm2835-cpufreq: switching to governor ondemand
[ 31.536231] Adding 102396k swap on /var/swap. Priority:-1 extents:1 across:102396k SS
[ 1713.768733] stk1160: fourcc format 0x32315659 invalid
[ 1713.768977] stk1160: fourcc format 0x32315559 invalid
[ 1713.769980] stk1160: registers to NTSC like standard
[ 1713.773115] stk1160: queue_setup: buffer count 8, each 691200 bytes
[ 1713.787883] Allocated vmalloc buffer of size 691200 at vaddr=c89c4000
[ 1713.804692] Allocated vmalloc buffer of size 691200 at vaddr=c8a70000
[ 1713.818062] Allocated vmalloc buffer of size 691200 at vaddr=c8b1c000
[ 1713.823285] Allocated vmalloc buffer of size 691200 at vaddr=c8bc8000
[ 1713.835108] Allocated vmalloc buffer of size 691200 at vaddr=c8c74000
[ 1713.839141] Allocated vmalloc buffer of size 691200 at vaddr=c8d20000
[ 1713.845853] Allocated vmalloc buffer of size 691200 at vaddr=c8dcc000
[ 1713.853942] Allocated vmalloc buffer of size 691200 at vaddr=c8e78000
[ 1713.854476] stk1160: vma=0xc6859d88
[ 1713.854960] stk1160: vma start=0x42e0f000, size=692224 (0)
[ 1713.855048] stk1160: vma=0xc6859d30
[ 1713.855534] stk1160: vma start=0x431a1000, size=692224 (0)
[ 1713.855603] stk1160: vma=0xc6859cd8
[ 1713.856067] stk1160: vma start=0x43276000, size=692224 (0)
[ 1713.856132] stk1160: vma=0xc6859c80
[ 1713.856691] stk1160: vma start=0x43419000, size=692224 (0)
[ 1713.856771] stk1160: vma=0xc6859c28
[ 1713.858505] stk1160: vma start=0x43594000, size=692224 (0)
[ 1713.858632] stk1160: vma=0xc6859bd0
[ 1713.859112] stk1160: vma start=0x436ad000, size=692224 (0)
[ 1713.862765] stk1160: vma=0xc6859b78
[ 1713.863997] stk1160: vma start=0x43813000, size=692224 (0)
[ 1713.864121] stk1160: vma=0xc6859b20
[ 1713.866401] stk1160: vma start=0x4390f000, size=692224 (0)
[ 1713.872850] stk1160: setting alternate 5
[ 1713.872874] stk1160: minimum isoc packet size: 3072 (alt=5)
[ 1713.872887] stk1160: setting alt 5 with wMaxPacketSize=3072
[ 1713.953838] stk1160: streaming started
[ 1714.030353] URB packet 0, status -63 [Buffer error (overrun)].
[ 1714.263734] URB packet 24, status -63 [Buffer error (overrun)].
[ 1714.283196] URB packet 1, status -63 [Buffer error (overrun)].
[ 1714.294138] URB packet 49, status -63 [Buffer error (overrun)].
[ 1714.303596] URB packet 17, status -63 [Buffer error (overrun)].
[ 1714.304695] URB packet 52, status -63 [Buffer error (overrun)].
[ 1714.323514] URB packet 20, status -63 [Buffer error (overrun)].
[ 1714.343341] URB packet 23, status -63 [Buffer error (overrun)].
[ 1714.352747] URB packet 0, status -63 [Buffer error (overrun)].
[ 1714.422400] URB packet 0, status -63 [Buffer error (overrun)].
[ 1719.043661] print_err_status: 183 callbacks suppressed
[ 1719.043688] URB packet 0, status -63 [Buffer error (overrun)].
[ 1719.045354] URB packet 55, status -63 [Buffer error (overrun)].
[ 1719.053709] URB packet 1, status -63 [Buffer error (overrun)].
[ 1719.094710] URB packet 49, status -63 [Buffer error (overrun)].
[ 1719.115224] URB packet 63, status -63 [Buffer error (overrun)].
[ 1719.124840] URB packet 45, status -63 [Buffer error (overrun)].
[ 1719.134371] URB packet 39, status -63 [Buffer error (overrun)].
[ 1719.164838] URB packet 33, status -63 [Buffer error (overrun)].
[ 1719.185045] URB packet 32, status -63 [Buffer error (overrun)].
[ 1719.213974] URB packet 15, status -63 [Buffer error (overrun)].
[ 1722.290875] stk1160: killing urbs...
[ 1722.291541] stk1160: all urbs killed
[ 1722.291566] stk1160: setting alternate 0
[ 1722.293150] stk1160: streaming stopped
[ 1722.294882] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c89c4000
[ 1722.295165] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8a70000
[ 1722.295417] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8b1c000
[ 1722.295646] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8bc8000
[ 1722.295882] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8c74000
[ 1722.296115] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8d20000
[ 1722.296362] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8dcc000
[ 1722.306282] vb2_vmalloc_put: Freeing vmalloc mem at vaddr=c8e78000
root@raspberrypi:/home/pi#

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

For my SD card class 4(around 5MB/s) I see:

For SD card class 10 (around 19-20MB/s) I see:

Maybe is SD card bottleneck?

@popcornmix
Copy link
Collaborator

I think the problem is we're not real time enough for high data rate isochronous USB transactions.
The main reason is the USB driver is all done software and interrupt driven, and high interrupt latency causes lost packets. isochronous USB doesn't allow for retransmits is the microframe is missed.
Now, the main cause for bad interrupt latency is the sdcard driver. A faster sdcard driver involved less time communicating with it, with interrupts disabled.
There is a command line option:
sdhci-bcm2708.sync_after_dma=0
which does avoid some of the busy waiting in the sdcard driver. However it doesn't work with all sdcards.
Give that a try (after backing up sdcard).

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

I cannot run sdhci-bcm2708.sync_after_dma=0 in command line.
Is this option in a config file?
How can I switch this option?

@popcornmix
Copy link
Collaborator

Add it to /boot/cmdline.txt.

@piotr-e
Copy link
Author

piotr-e commented Oct 17, 2012

I've done it but I don't notice any perceptible difference in the output for both SDs.

@piotr-e
Copy link
Author

piotr-e commented Oct 18, 2012

@popcornmix, is it possible to fix this USB driver? Are you Raspberry Pi programmer?

@DAFlippers
Copy link

It is being worked on but it's not a simple fix #79.

David

@P33M
Copy link
Contributor

P33M commented May 5, 2014

Isochronous is now orders of magnitude more reliable with fiq_fsm.

@P33M P33M closed this as completed May 5, 2014
popcornmix pushed a commit that referenced this issue Dec 2, 2015
Currently it's assumed that firmware exports only the class of sensors
supported by the driver. However with newer firmware or SCPI protocol
revision, support for newer classes of sensors can be present.

The driver fails to probe with the following warning if an unsupported
class of sensor is encountered in the firmware.

sysfs: cannot create duplicate filename
	'/devices/platform/scpi/scpi:sensors/hwmon/hwmon0/'
------------[ cut here ]------------
WARNING: at fs/sysfs/dir.c:31
Modules linked in:

CPU: 0 PID: 6 Comm: kworker/u12:0 Not tainted 4.3.0-rc7 #137
Hardware name: ARM Juno development board (r0) (DT)
Workqueue: deferwq deferred_probe_work_func
PC is at sysfs_warn_dup+0x54/0x78
LR is at sysfs_warn_dup+0x54/0x78

This patch fixes the above issue by skipping through the unsupported
class of SCPI sensors.

Fixes: 68acc77 ("hwmon: Support thermal zones registration for SCP temperature sensors")
Fixes: ea98b29 ("hwmon: Support sensors exported via ARM SCP interface")
Cc: Guenter Roeck <linux@roeck-us.net>
Reviewed-by: Punit Agrawal <punit.agrawal@arm.com>
Signed-off-by: Sudeep Holla <sudeep.holla@arm.com>
Signed-off-by: Guenter Roeck <linux@roeck-us.net>
popcornmix pushed a commit that referenced this issue Dec 2, 2015
OMAP CPU hotplug uses cpu1's clocks and power domains for CPU1 wake up
from low power states (or turn on CPU1). This part of code is also
part of system suspend (disable_nonboot_cpus()).
>From other side, cpu1's clocks and power domains are used by CPUIdle. All above
functionality is mutually exclusive and, therefore, lockless clkdm/pwrdm api
can be used in omap4_boot_secondary().

This fixes below back-trace on -RT which is triggered by
pwrdm_lock/unlock():

BUG: sleeping function called from invalid context at kernel/locking/rtmutex.c:917
 in_atomic(): 1, irqs_disabled(): 0, pid: 118, name: sh
 9 locks held by sh/118:
  #0:  (sb_writers#4){.+.+.+}, at: [<c0144a6c>] vfs_write+0x13c/0x164
  #1:  (&of->mutex){+.+.+.}, at: [<c01b4c70>] kernfs_fop_write+0x48/0x19c
  #2:  (s_active#24){.+.+.+}, at: [<c01b4c78>] kernfs_fop_write+0x50/0x19c
  #3:  (device_hotplug_lock){+.+.+.}, at: [<c03cbff0>] lock_device_hotplug_sysfs+0xc/0x4c
  #4:  (&dev->mutex){......}, at: [<c03cd284>] device_online+0x14/0x88
  #5:  (cpu_add_remove_lock){+.+.+.}, at: [<c003af90>] cpu_up+0x50/0x1a0
  #6:  (cpu_hotplug.lock){++++++}, at: [<c003ae48>] cpu_hotplug_begin+0x0/0xc4
  #7:  (cpu_hotplug.lock#2){+.+.+.}, at: [<c003aec0>] cpu_hotplug_begin+0x78/0xc4
  #8:  (boot_lock){+.+...}, at: [<c002b254>] omap4_boot_secondary+0x1c/0x178
 Preemption disabled at:[<  (null)>]   (null)

 CPU: 0 PID: 118 Comm: sh Not tainted 4.1.12-rt11-01998-gb4a62c3-dirty #137
 Hardware name: Generic DRA74X (Flattened Device Tree)
 [<c0017574>] (unwind_backtrace) from [<c0013be8>] (show_stack+0x10/0x14)
 [<c0013be8>] (show_stack) from [<c05a8670>] (dump_stack+0x80/0x94)
 [<c05a8670>] (dump_stack) from [<c05ad158>] (rt_spin_lock+0x24/0x54)
 [<c05ad158>] (rt_spin_lock) from [<c0030dac>] (clkdm_wakeup+0x10/0x2c)
 [<c0030dac>] (clkdm_wakeup) from [<c002b2c0>] (omap4_boot_secondary+0x88/0x178)
 [<c002b2c0>] (omap4_boot_secondary) from [<c0015d00>] (__cpu_up+0xc4/0x164)
 [<c0015d00>] (__cpu_up) from [<c003b09c>] (cpu_up+0x15c/0x1a0)
 [<c003b09c>] (cpu_up) from [<c03cd2d4>] (device_online+0x64/0x88)
 [<c03cd2d4>] (device_online) from [<c03cd360>] (online_store+0x68/0x74)
 [<c03cd360>] (online_store) from [<c01b4ce0>] (kernfs_fop_write+0xb8/0x19c)
 [<c01b4ce0>] (kernfs_fop_write) from [<c0144124>] (__vfs_write+0x20/0xd8)
 [<c0144124>] (__vfs_write) from [<c01449c0>] (vfs_write+0x90/0x164)
 [<c01449c0>] (vfs_write) from [<c01451e4>] (SyS_write+0x44/0x9c)
 [<c01451e4>] (SyS_write) from [<c0010240>] (ret_fast_syscall+0x0/0x54)
 CPU1: smp_ops.cpu_die() returned, trying to resuscitate

Cc: Tero Kristo <t-kristo@ti.com>
Signed-off-by: Grygorii Strashko <grygorii.strashko@ti.com>
Signed-off-by: Tony Lindgren <tony@atomide.com>
popcornmix pushed a commit that referenced this issue Dec 12, 2017
In tipc_topsrv_kern_subscr() when s->tipc_conn_new() fails
we call tipc_close_conn() to clean up, but in this case
calling conn_put() is just enough.

This fixes the folllowing crash:

 kasan: GPF could be caused by NULL-ptr deref or user memory access
 general protection fault: 0000 [#1] SMP KASAN
 Dumping ftrace buffer:
    (ftrace buffer empty)
 Modules linked in:
 CPU: 0 PID: 3085 Comm: syzkaller064164 Not tainted 4.15.0-rc1+ #137
 Hardware name: Google Google Compute Engine/Google Compute Engine, BIOS Google 01/01/2011
 task: 00000000c24413a5 task.stack: 000000005e8160b5
 RIP: 0010:__lock_acquire+0xd55/0x47f0 kernel/locking/lockdep.c:3378
 RSP: 0018:ffff8801cb5474a8 EFLAGS: 00010002
 RAX: dffffc0000000000 RBX: 0000000000000000 RCX: 0000000000000000
 RDX: 0000000000000004 RSI: 0000000000000000 RDI: ffffffff85ecb400
 RBP: ffff8801cb547830 R08: 0000000000000001 R09: 0000000000000000
 R10: 0000000000000000 R11: ffffffff87489d60 R12: ffff8801cd2980c0
 R13: 0000000000000000 R14: 0000000000000001 R15: 0000000000000020
 FS:  00000000014ee880(0000) GS:ffff8801db400000(0000) knlGS:0000000000000000
 CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
 CR2: 00007ffee2426e40 CR3: 00000001cb85a000 CR4: 00000000001406f0
 DR0: 0000000000000000 DR1: 0000000000000000 DR2: 0000000000000000
 DR3: 0000000000000000 DR6: 00000000fffe0ff0 DR7: 0000000000000400
 Call Trace:
  lock_acquire+0x1d5/0x580 kernel/locking/lockdep.c:4004
  __raw_spin_lock_bh include/linux/spinlock_api_smp.h:135 [inline]
  _raw_spin_lock_bh+0x31/0x40 kernel/locking/spinlock.c:175
  spin_lock_bh include/linux/spinlock.h:320 [inline]
  tipc_subscrb_subscrp_delete+0x8f/0x470 net/tipc/subscr.c:201
  tipc_subscrb_delete net/tipc/subscr.c:238 [inline]
  tipc_subscrb_release_cb+0x17/0x30 net/tipc/subscr.c:316
  tipc_close_conn+0x171/0x270 net/tipc/server.c:204
  tipc_topsrv_kern_subscr+0x724/0x810 net/tipc/server.c:514
  tipc_group_create+0x702/0x9c0 net/tipc/group.c:184
  tipc_sk_join net/tipc/socket.c:2747 [inline]
  tipc_setsockopt+0x249/0xc10 net/tipc/socket.c:2861
  SYSC_setsockopt net/socket.c:1851 [inline]
  SyS_setsockopt+0x189/0x360 net/socket.c:1830
  entry_SYSCALL_64_fastpath+0x1f/0x96

Fixes: 14c0449 ("tipc: add ability to order and receive topology events in driver")
Reported-by: syzbot <syzkaller@googlegroups.com>
Cc: Jon Maloy <jon.maloy@ericsson.com>
Cc: Ying Xue <ying.xue@windriver.com>
Signed-off-by: Cong Wang <xiyou.wangcong@gmail.com>
Signed-off-by: David S. Miller <davem@davemloft.net>
popcornmix pushed a commit that referenced this issue Oct 2, 2020
[ Upstream commit 402f299 ]

When use command to read values, it crashed.

command:
dd if=/sys/kernel/debug/ieee80211/phy0/ath10k/mem_value count=1 bs=4 skip=$((0x100233))

It will call to ath10k_sdio_hif_diag_read with address = 0x4008cc and buf_len = 4.

Then system crash:
[ 1786.013258] Unable to handle kernel paging request at virtual address ffffffc00bd45000
[ 1786.013273] Mem abort info:
[ 1786.013281]   ESR = 0x96000045
[ 1786.013291]   Exception class = DABT (current EL), IL = 32 bits
[ 1786.013299]   SET = 0, FnV = 0
[ 1786.013307]   EA = 0, S1PTW = 0
[ 1786.013314] Data abort info:
[ 1786.013322]   ISV = 0, ISS = 0x00000045
[ 1786.013330]   CM = 0, WnR = 1
[ 1786.013342] swapper pgtable: 4k pages, 39-bit VAs, pgdp = 000000008542a60e
[ 1786.013350] [ffffffc00bd45000] pgd=0000000000000000, pud=0000000000000000
[ 1786.013368] Internal error: Oops: 96000045 [#1] PREEMPT SMP
[ 1786.013609] Process swapper/0 (pid: 0, stack limit = 0x0000000084b153c6)
[ 1786.013623] CPU: 0 PID: 0 Comm: swapper/0 Not tainted 4.19.86 #137
[ 1786.013631] Hardware name: MediaTek krane sku176 board (DT)
[ 1786.013643] pstate: 80000085 (Nzcv daIf -PAN -UAO)
[ 1786.013662] pc : __memcpy+0x94/0x180
[ 1786.013678] lr : swiotlb_tbl_unmap_single+0x84/0x150
[ 1786.013686] sp : ffffff8008003c60
[ 1786.013694] x29: ffffff8008003c90 x28: ffffffae96411f80
[ 1786.013708] x27: ffffffae960d2018 x26: ffffff8019a4b9a8
[ 1786.013721] x25: 0000000000000000 x24: 0000000000000001
[ 1786.013734] x23: ffffffae96567000 x22: 00000000000051d4
[ 1786.013747] x21: 0000000000000000 x20: 00000000fe6e9000
[ 1786.013760] x19: 0000000000000004 x18: 0000000000000020
[ 1786.013773] x17: 0000000000000001 x16: 0000000000000000
[ 1786.013787] x15: 00000000ffffffff x14: 00000000000044c0
[ 1786.013800] x13: 0000000000365ba4 x12: 0000000000000000
[ 1786.013813] x11: 0000000000000001 x10: 00000037be6e9000
[ 1786.013826] x9 : ffffffc940000000 x8 : 000000000bd45000
[ 1786.013839] x7 : 0000000000000000 x6 : ffffffc00bd45000
[ 1786.013852] x5 : 0000000000000000 x4 : 0000000000000000
[ 1786.013865] x3 : 0000000000000c00 x2 : 0000000000000004
[ 1786.013878] x1 : fffffff7be6e9004 x0 : ffffffc00bd45000
[ 1786.013891] Call trace:
[ 1786.013903]  __memcpy+0x94/0x180
[ 1786.013914]  unmap_single+0x6c/0x84
[ 1786.013925]  swiotlb_unmap_sg_attrs+0x54/0x80
[ 1786.013938]  __swiotlb_unmap_sg_attrs+0x8c/0xa4
[ 1786.013952]  msdc_unprepare_data+0x6c/0x84
[ 1786.013963]  msdc_request_done+0x58/0x84
[ 1786.013974]  msdc_data_xfer_done+0x1a0/0x1c8
[ 1786.013985]  msdc_irq+0x12c/0x17c
[ 1786.013996]  __handle_irq_event_percpu+0xe4/0x250
[ 1786.014006]  handle_irq_event_percpu+0x28/0x68
[ 1786.014015]  handle_irq_event+0x48/0x78
[ 1786.014026]  handle_fasteoi_irq+0xd0/0x1a0
[ 1786.014039]  __handle_domain_irq+0x84/0xc4
[ 1786.014050]  gic_handle_irq+0x124/0x1a4
[ 1786.014059]  el1_irq+0xb0/0x128
[ 1786.014072]  cpuidle_enter_state+0x298/0x328
[ 1786.014082]  cpuidle_enter+0x30/0x40
[ 1786.014094]  do_idle+0x190/0x268
[ 1786.014104]  cpu_startup_entry+0x24/0x28
[ 1786.014116]  rest_init+0xd4/0xe0
[ 1786.014126]  start_kernel+0x30c/0x38c
[ 1786.014139] Code: f8408423 f80084c3 36100062 b8404423 (b80044c3)
[ 1786.014150] ---[ end trace 3b02ddb698ea69ee ]---
[ 1786.015415] Kernel panic - not syncing: Fatal exception in interrupt
[ 1786.015433] SMP: stopping secondary CPUs
[ 1786.015447] Kernel Offset: 0x2e8d200000 from 0xffffff8008000000
[ 1786.015458] CPU features: 0x0,2188200c
[ 1786.015466] Memory Limit: none

For sdio chip, it need the memory which is kmalloc, if it is
vmalloc from ath10k_mem_value_read, then it have a memory error.
kzalloc of ath10k_sdio_hif_diag_read32 is the correct type, so
add kzalloc in ath10k_sdio_hif_diag_read to replace the buffer
which is vmalloc from ath10k_mem_value_read.

This patch only effect sdio chip.

Tested with QCA6174 SDIO with firmware WLAN.RMH.4.4.1-00029.

Signed-off-by: Wen Gong <wgong@codeaurora.org>
Signed-off-by: Kalle Valo <kvalo@codeaurora.org>
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Nov 9, 2020
Michal Privoznik was using "free page reporting" in QEMU/virtio-balloon
with hugetlbfs and hit the warning below.  QEMU with free page hinting
uses fallocate(FALLOC_FL_PUNCH_HOLE) to discard pages that are reported
as free by a VM.  The reporting granularity is in pageblock granularity.
So when the guest reports 2M chunks, we fallocate(FALLOC_FL_PUNCH_HOLE)
one huge page in QEMU.

  WARNING: CPU: 7 PID: 6636 at mm/page_counter.c:57 page_counter_uncharge+0x4b/0x50
  Modules linked in: ...
  CPU: 7 PID: 6636 Comm: qemu-system-x86 Not tainted 5.9.0 #137
  Hardware name: Gigabyte Technology Co., Ltd. X570 AORUS PRO/X570 AORUS PRO, BIOS F21 07/31/2020
  RIP: 0010:page_counter_uncharge+0x4b/0x50
  ...
  Call Trace:
    hugetlb_cgroup_uncharge_file_region+0x4b/0x80
    region_del+0x1d3/0x300
    hugetlb_unreserve_pages+0x39/0xb0
    remove_inode_hugepages+0x1a8/0x3d0
    hugetlbfs_fallocate+0x3c4/0x5c0
    vfs_fallocate+0x146/0x290
    __x64_sys_fallocate+0x3e/0x70
    do_syscall_64+0x33/0x40
    entry_SYSCALL_64_after_hwframe+0x44/0xa9

Investigation of the issue uncovered bugs in hugetlb cgroup reservation
accounting.  This patch addresses the found issues.

Fixes: 075a61d ("hugetlb_cgroup: add accounting for shared mappings")
Reported-by: Michal Privoznik <mprivozn@redhat.com>
Co-developed-by: David Hildenbrand <david@redhat.com>
Signed-off-by: David Hildenbrand <david@redhat.com>
Signed-off-by: Mike Kravetz <mike.kravetz@oracle.com>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Tested-by: Michal Privoznik <mprivozn@redhat.com>
Reviewed-by: Mina Almasry <almasrymina@google.com>
Acked-by: Michael S. Tsirkin <mst@redhat.com>
Cc: <stable@vger.kernel.org>
Cc: David Hildenbrand <david@redhat.com>
Cc: Michal Hocko <mhocko@kernel.org>
Cc: Muchun Song <songmuchun@bytedance.com>
Cc: "Aneesh Kumar K . V" <aneesh.kumar@linux.vnet.ibm.com>
Cc: Tejun Heo <tj@kernel.org>
Link: https://lkml.kernel.org/r/20201021204426.36069-1-mike.kravetz@oracle.com
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
popcornmix pushed a commit that referenced this issue Nov 17, 2020
commit 79aa925 upstream.

Michal Privoznik was using "free page reporting" in QEMU/virtio-balloon
with hugetlbfs and hit the warning below.  QEMU with free page hinting
uses fallocate(FALLOC_FL_PUNCH_HOLE) to discard pages that are reported
as free by a VM.  The reporting granularity is in pageblock granularity.
So when the guest reports 2M chunks, we fallocate(FALLOC_FL_PUNCH_HOLE)
one huge page in QEMU.

  WARNING: CPU: 7 PID: 6636 at mm/page_counter.c:57 page_counter_uncharge+0x4b/0x50
  Modules linked in: ...
  CPU: 7 PID: 6636 Comm: qemu-system-x86 Not tainted 5.9.0 #137
  Hardware name: Gigabyte Technology Co., Ltd. X570 AORUS PRO/X570 AORUS PRO, BIOS F21 07/31/2020
  RIP: 0010:page_counter_uncharge+0x4b/0x50
  ...
  Call Trace:
    hugetlb_cgroup_uncharge_file_region+0x4b/0x80
    region_del+0x1d3/0x300
    hugetlb_unreserve_pages+0x39/0xb0
    remove_inode_hugepages+0x1a8/0x3d0
    hugetlbfs_fallocate+0x3c4/0x5c0
    vfs_fallocate+0x146/0x290
    __x64_sys_fallocate+0x3e/0x70
    do_syscall_64+0x33/0x40
    entry_SYSCALL_64_after_hwframe+0x44/0xa9

Investigation of the issue uncovered bugs in hugetlb cgroup reservation
accounting.  This patch addresses the found issues.

Fixes: 075a61d ("hugetlb_cgroup: add accounting for shared mappings")
Reported-by: Michal Privoznik <mprivozn@redhat.com>
Co-developed-by: David Hildenbrand <david@redhat.com>
Signed-off-by: David Hildenbrand <david@redhat.com>
Signed-off-by: Mike Kravetz <mike.kravetz@oracle.com>
Signed-off-by: Andrew Morton <akpm@linux-foundation.org>
Tested-by: Michal Privoznik <mprivozn@redhat.com>
Reviewed-by: Mina Almasry <almasrymina@google.com>
Acked-by: Michael S. Tsirkin <mst@redhat.com>
Cc: <stable@vger.kernel.org>
Cc: David Hildenbrand <david@redhat.com>
Cc: Michal Hocko <mhocko@kernel.org>
Cc: Muchun Song <songmuchun@bytedance.com>
Cc: "Aneesh Kumar K . V" <aneesh.kumar@linux.vnet.ibm.com>
Cc: Tejun Heo <tj@kernel.org>
Link: https://lkml.kernel.org/r/20201021204426.36069-1-mike.kravetz@oracle.com
Signed-off-by: Linus Torvalds <torvalds@linux-foundation.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Mar 16, 2021
[ Upstream commit e2f8b74 ]

It happened "Kernel panic - not syncing: hung_task: blocked tasks" when
test simulate crash and ifconfig down/rmmod meanwhile.

Test steps:

1.Test commands, either can reproduce the hang for PCIe, SDIO and SNOC.
echo soft > /sys/kernel/debug/ieee80211/phy0/ath10k/simulate_fw_crash;sleep 0.05;ifconfig wlan0 down
echo soft > /sys/kernel/debug/ieee80211/phy0/ath10k/simulate_fw_crash;rmmod ath10k_sdio
echo hw-restart > /sys/kernel/debug/ieee80211/phy0/ath10k/simulate_fw_crash;rmmod ath10k_pci

2. dmesg:
[ 5622.548630] ath10k_sdio mmc1:0001:1: simulating soft firmware crash
[ 5622.655995] ieee80211 phy0: Hardware restart was requested
[ 5776.355164] INFO: task shill:1572 blocked for more than 122 seconds.
[ 5776.355687] INFO: task kworker/1:2:24437 blocked for more than 122 seconds.
[ 5776.359812] Kernel panic - not syncing: hung_task: blocked tasks
[ 5776.359836] CPU: 1 PID: 55 Comm: khungtaskd Tainted: G        W         4.19.86 #137
[ 5776.359846] Hardware name: MediaTek krane sku176 board (DT)
[ 5776.359855] Call trace:
[ 5776.359868]  dump_backtrace+0x0/0x170
[ 5776.359881]  show_stack+0x20/0x2c
[ 5776.359896]  dump_stack+0xd4/0x10c
[ 5776.359916]  panic+0x12c/0x29c
[ 5776.359937]  hung_task_panic+0x0/0x50
[ 5776.359953]  kthread+0x120/0x130
[ 5776.359965]  ret_from_fork+0x10/0x18
[ 5776.359986] SMP: stopping secondary CPUs
[ 5776.360012] Kernel Offset: 0x141ea00000 from 0xffffff8008000000
[ 5776.360026] CPU features: 0x0,2188200c
[ 5776.360035] Memory Limit: none

command "ifconfig wlan0 down" or "rmmod ath10k_sdio" will be blocked
callstack of ifconfig:
[<0>] __switch_to+0x120/0x13c
[<0>] msleep+0x28/0x38
[<0>] ath10k_sdio_hif_stop+0x24c/0x294 [ath10k_sdio]
[<0>] ath10k_core_stop+0x50/0x78 [ath10k_core]
[<0>] ath10k_halt+0x120/0x178 [ath10k_core]
[<0>] ath10k_stop+0x4c/0x8c [ath10k_core]
[<0>] drv_stop+0xe0/0x1e4 [mac80211]
[<0>] ieee80211_stop_device+0x48/0x54 [mac80211]
[<0>] ieee80211_do_stop+0x678/0x6f8 [mac80211]
[<0>] ieee80211_stop+0x20/0x30 [mac80211]
[<0>] __dev_close_many+0xb8/0x11c
[<0>] __dev_change_flags+0xe0/0x1d0
[<0>] dev_change_flags+0x30/0x6c
[<0>] devinet_ioctl+0x370/0x564
[<0>] inet_ioctl+0xdc/0x304
[<0>] sock_do_ioctl+0x50/0x288
[<0>] compat_sock_ioctl+0x1b4/0x1aac
[<0>] __se_compat_sys_ioctl+0x100/0x26fc
[<0>] __arm64_compat_sys_ioctl+0x20/0x2c
[<0>] el0_svc_common+0xa4/0x154
[<0>] el0_svc_compat_handler+0x2c/0x38
[<0>] el0_svc_compat+0x8/0x18
[<0>] 0xffffffffffffffff

callstack of rmmod:
[<0>] __switch_to+0x120/0x13c
[<0>] msleep+0x28/0x38
[<0>] ath10k_sdio_hif_stop+0x294/0x31c [ath10k_sdio]
[<0>] ath10k_core_stop+0x50/0x78 [ath10k_core]
[<0>] ath10k_halt+0x120/0x178 [ath10k_core]
[<0>] ath10k_stop+0x4c/0x8c [ath10k_core]
[<0>] drv_stop+0xe0/0x1e4 [mac80211]
[<0>] ieee80211_stop_device+0x48/0x54 [mac80211]
[<0>] ieee80211_do_stop+0x678/0x6f8 [mac80211]
[<0>] ieee80211_stop+0x20/0x30 [mac80211]
[<0>] __dev_close_many+0xb8/0x11c
[<0>] dev_close_many+0x70/0x100
[<0>] dev_close+0x4c/0x80
[<0>] cfg80211_shutdown_all_interfaces+0x50/0xcc [cfg80211]
[<0>] ieee80211_remove_interfaces+0x58/0x1a0 [mac80211]
[<0>] ieee80211_unregister_hw+0x40/0x100 [mac80211]
[<0>] ath10k_mac_unregister+0x1c/0x44 [ath10k_core]
[<0>] ath10k_core_unregister+0x38/0x7c [ath10k_core]
[<0>] ath10k_sdio_remove+0x8c/0xd0 [ath10k_sdio]
[<0>] sdio_bus_remove+0x48/0x108
[<0>] device_release_driver_internal+0x138/0x1ec
[<0>] driver_detach+0x6c/0xa8
[<0>] bus_remove_driver+0x78/0xa8
[<0>] driver_unregister+0x30/0x50
[<0>] sdio_unregister_driver+0x28/0x34
[<0>] cleanup_module+0x14/0x6bc [ath10k_sdio]
[<0>] __arm64_sys_delete_module+0x1e0/0x22c
[<0>] el0_svc_common+0xa4/0x154
[<0>] el0_svc_compat_handler+0x2c/0x38
[<0>] el0_svc_compat+0x8/0x18
[<0>] 0xffffffffffffffff

SNOC:
[  647.156863] Call trace:
[  647.162166] [<ffffff80080855a4>] __switch_to+0x120/0x13c
[  647.164512] [<ffffff800899d8b8>] __schedule+0x5ec/0x798
[  647.170062] [<ffffff800899dad8>] schedule+0x74/0x94
[  647.175050] [<ffffff80089a0848>] schedule_timeout+0x314/0x42c
[  647.179874] [<ffffff80089a0a14>] schedule_timeout_uninterruptible+0x34/0x40
[  647.185780] [<ffffff80082a494>] msleep+0x28/0x38
[  647.192546] [<ffffff800117ec4c>] ath10k_snoc_hif_stop+0x4c/0x1e0 [ath10k_snoc]
[  647.197439] [<ffffff80010dfbd8>] ath10k_core_stop+0x50/0x7c [ath10k_core]
[  647.204652] [<ffffff80010c8f48>] ath10k_halt+0x114/0x16c [ath10k_core]
[  647.211420] [<ffffff80010cad68>] ath10k_stop+0x4c/0x88 [ath10k_core]
[  647.217865] [<ffffff8000fdbf54>] drv_stop+0x110/0x244 [mac80211]
[  647.224367] [<ffffff80010147ac>] ieee80211_stop_device+0x48/0x54 [mac80211]
[  647.230359] [<ffffff8000ff3eec>] ieee80211_do_stop+0x6a4/0x73c [mac80211]
[  647.237033] [<ffffff8000ff4500>] ieee80211_stop+0x20/0x30 [mac80211]
[  647.243942] [<ffffff80087e39b8>] __dev_close_many+0xa0/0xfc
[  647.250435] [<ffffff80087e3888>] dev_close_many+0x70/0x100
[  647.255651] [<ffffff80087e3a60>] dev_close+0x4c/0x80
[  647.261244] [<ffffff8000f1ba54>] cfg80211_shutdown_all_interfaces+0x44/0xcc [cfg80211]
[  647.266383] [<ffffff8000ff3fdc>] ieee80211_remove_interfaces+0x58/0x1b4 [mac80211]
[  647.274128] [<ffffff8000fda540>] ieee80211_unregister_hw+0x50/0x120 [mac80211]
[  647.281659] [<ffffff80010ca314>] ath10k_mac_unregister+0x1c/0x44 [ath10k_core]
[  647.288839] [<ffffff80010dfc94>] ath10k_core_unregister+0x48/0x90 [ath10k_core]
[  647.296027] [<ffffff800117e598>] ath10k_snoc_remove+0x5c/0x150 [ath10k_snoc]
[  647.303229] [<ffffff80085625fc>] platform_drv_remove+0x28/0x50
[  647.310517] [<ffffff80085601a4>] device_release_driver_internal+0x114/0x1b8
[  647.316257] [<ffffff80085602e4>] driver_detach+0x6c/0xa8
[  647.323021] [<ffffff800855e5b8>] bus_remove_driver+0x78/0xa8
[  647.328571] [<ffffff800856107c>] driver_unregister+0x30/0x50
[  647.334213] [<ffffff8008562674>] platform_driver_unregister+0x1c/0x28
[  647.339876] [<ffffff800117fefc>] cleanup_module+0x1c/0x120 [ath10k_snoc]
[  647.346196] [<ffffff8008143ab8>] SyS_delete_module+0x1dc/0x22c

PCIe:
[  615.392770] rmmod           D    0  3523   3458 0x00000080
[  615.392777] Call Trace:
[  615.392784]  __schedule+0x617/0x7d3
[  615.392791]  ? __mod_timer+0x263/0x35c
[  615.392797]  schedule+0x62/0x72
[  615.392803]  schedule_timeout+0x8d/0xf3
[  615.392809]  ? run_local_timers+0x6b/0x6b
[  615.392814]  msleep+0x1b/0x22
[  615.392824]  ath10k_pci_hif_stop+0x68/0xd6 [ath10k_pci]
[  615.392844]  ath10k_core_stop+0x44/0x67 [ath10k_core]
[  615.392859]  ath10k_halt+0x102/0x153 [ath10k_core]
[  615.392873]  ath10k_stop+0x38/0x75 [ath10k_core]
[  615.392893]  drv_stop+0x9a/0x13c [mac80211]
[  615.392915]  ieee80211_do_stop+0x772/0x7cd [mac80211]
[  615.392937]  ieee80211_stop+0x1a/0x1e [mac80211]
[  615.392945]  __dev_close_many+0x9e/0xf0
[  615.392952]  dev_close_many+0x62/0xe8
[  615.392958]  dev_close+0x54/0x7d
[  615.392975]  cfg80211_shutdown_all_interfaces+0x6e/0xa5 [cfg80211]
[  615.393021]  ieee80211_remove_interfaces+0x52/0x1aa [mac80211]
[  615.393049]  ieee80211_unregister_hw+0x54/0x136 [mac80211]
[  615.393068]  ath10k_mac_unregister+0x19/0x4a [ath10k_core]
[  615.393091]  ath10k_core_unregister+0x39/0x7e [ath10k_core]
[  615.393104]  ath10k_pci_remove+0x3d/0x7f [ath10k_pci]
[  615.393117]  pci_device_remove+0x41/0xa6
[  615.393129]  device_release_driver_internal+0x123/0x1ec
[  615.393140]  driver_detach+0x60/0x90
[  615.393152]  bus_remove_driver+0x72/0x9f
[  615.393164]  pci_unregister_driver+0x1e/0x87
[  615.393177]  SyS_delete_module+0x1d7/0x277
[  615.393188]  do_syscall_64+0x6b/0xf7
[  615.393199]  entry_SYSCALL_64_after_hwframe+0x41/0xa6

The test command run simulate_fw_crash firstly and it call into
ath10k_sdio_hif_stop from ath10k_core_restart, then napi_disable
is called and bit NAPI_STATE_SCHED is set. After that, function
ath10k_sdio_hif_stop is called again from ath10k_stop by command
"ifconfig wlan0 down" or "rmmod ath10k_sdio", then command blocked.

It is blocked by napi_synchronize, napi_disable will set bit with
NAPI_STATE_SCHED, and then napi_synchronize will enter dead loop
becuase bit NAPI_STATE_SCHED is set by napi_disable.

function of napi_synchronize
static inline void napi_synchronize(const struct napi_struct *n)
{
	if (IS_ENABLED(CONFIG_SMP))
		while (test_bit(NAPI_STATE_SCHED, &n->state))
			msleep(1);
	else
		barrier();
}

function of napi_disable
void napi_disable(struct napi_struct *n)
{
	might_sleep();
	set_bit(NAPI_STATE_DISABLE, &n->state);

	while (test_and_set_bit(NAPI_STATE_SCHED, &n->state))
		msleep(1);
	while (test_and_set_bit(NAPI_STATE_NPSVC, &n->state))
		msleep(1);

	hrtimer_cancel(&n->timer);

	clear_bit(NAPI_STATE_DISABLE, &n->state);
}

Add flag for it avoid the hang and crash.

Tested-on: QCA6174 hw3.2 SDIO WLAN.RMH.4.4.1-00049
Tested-on: QCA6174 hw3.2 PCI WLAN.RM.4.4.1-00110-QCARMSWP-1
Tested-on: WCN3990 hw1.0 SNOC hw1.0 WLAN.HL.3.1-01307.1-QCAHLSWMTPL-2

Signed-off-by: Wen Gong <wgong@codeaurora.org>
Signed-off-by: Kalle Valo <kvalo@codeaurora.org>
Link: https://lore.kernel.org/r/1598617348-2325-1-git-send-email-wgong@codeaurora.org
Signed-off-by: Sasha Levin <sashal@kernel.org>
popcornmix pushed a commit that referenced this issue Sep 23, 2021
We queue an irq work for deferred processing of mce event in realmode
mce handler, where translation is disabled. Queuing of the work may
result in accessing memory outside RMO region, such access needs the
translation to be enabled for an LPAR running with hash mmu else the
kernel crashes.

After enabling translation in mce_handle_error() we used to leave it
enabled to avoid crashing here, but now with the commit
74c3354 ("powerpc/pseries/mce: restore msr before returning from
handler") we are restoring the MSR to disable translation.

Hence to fix this enable the translation before queuing the work.

Without this change following trace is seen on injecting SLB multihit in
an LPAR running with hash mmu.

  Oops: Kernel access of bad area, sig: 11 [#1]
  LE PAGE_SIZE=64K MMU=Hash SMP NR_CPUS=2048 NUMA pSeries
  CPU: 5 PID: 1883 Comm: insmod Tainted: G        OE     5.14.0-mce+ #137
  NIP:  c000000000735d60 LR: c000000000318640 CTR: 0000000000000000
  REGS: c00000001ebff9a0 TRAP: 0300   Tainted: G       OE      (5.14.0-mce+)
  MSR:  8000000000001003 <SF,ME,RI,LE>  CR: 28008228  XER: 00000001
  CFAR: c00000000031863c DAR: c00000027fa8fe08 DSISR: 40000000 IRQMASK: 0
  ...
  NIP llist_add_batch+0x0/0x40
  LR  __irq_work_queue_local+0x70/0xc0
  Call Trace:
    0xc00000001ebffc0c (unreliable)
    irq_work_queue+0x40/0x70
    machine_check_queue_event+0xbc/0xd0
    machine_check_early_common+0x16c/0x1f4

Fixes: 74c3354 ("powerpc/pseries/mce: restore msr before returning from handler")
Signed-off-by: Ganesh Goudar <ganeshgr@linux.ibm.com>
[mpe: Fix comment formatting, trim oops in change log for readability]
Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
Link: https://lore.kernel.org/r/20210909064330.312432-1-ganeshgr@linux.ibm.com
popcornmix pushed a commit that referenced this issue Sep 30, 2021
commit 3a1e92d upstream.

We queue an irq work for deferred processing of mce event in realmode
mce handler, where translation is disabled. Queuing of the work may
result in accessing memory outside RMO region, such access needs the
translation to be enabled for an LPAR running with hash mmu else the
kernel crashes.

After enabling translation in mce_handle_error() we used to leave it
enabled to avoid crashing here, but now with the commit
74c3354 ("powerpc/pseries/mce: restore msr before returning from
handler") we are restoring the MSR to disable translation.

Hence to fix this enable the translation before queuing the work.

Without this change following trace is seen on injecting SLB multihit in
an LPAR running with hash mmu.

  Oops: Kernel access of bad area, sig: 11 [#1]
  LE PAGE_SIZE=64K MMU=Hash SMP NR_CPUS=2048 NUMA pSeries
  CPU: 5 PID: 1883 Comm: insmod Tainted: G        OE     5.14.0-mce+ #137
  NIP:  c000000000735d60 LR: c000000000318640 CTR: 0000000000000000
  REGS: c00000001ebff9a0 TRAP: 0300   Tainted: G       OE      (5.14.0-mce+)
  MSR:  8000000000001003 <SF,ME,RI,LE>  CR: 28008228  XER: 00000001
  CFAR: c00000000031863c DAR: c00000027fa8fe08 DSISR: 40000000 IRQMASK: 0
  ...
  NIP llist_add_batch+0x0/0x40
  LR  __irq_work_queue_local+0x70/0xc0
  Call Trace:
    0xc00000001ebffc0c (unreliable)
    irq_work_queue+0x40/0x70
    machine_check_queue_event+0xbc/0xd0
    machine_check_early_common+0x16c/0x1f4

Fixes: 74c3354 ("powerpc/pseries/mce: restore msr before returning from handler")
Signed-off-by: Ganesh Goudar <ganeshgr@linux.ibm.com>
[mpe: Fix comment formatting, trim oops in change log for readability]
Signed-off-by: Michael Ellerman <mpe@ellerman.id.au>
Link: https://lore.kernel.org/r/20210909064330.312432-1-ganeshgr@linux.ibm.com
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Nov 1, 2021
On Thundercomm TurboX CM2290, the eMMC OCR reports vdd = 23 (3.5 ~ 3.6 V),
which is being treated as an invalid value by sdhci_set_power_noreg().
And thus eMMC is totally broken on the platform.

[    1.436599] ------------[ cut here ]------------
[    1.436606] mmc0: Invalid vdd 0x17
[    1.436640] WARNING: CPU: 2 PID: 69 at drivers/mmc/host/sdhci.c:2048 sdhci_set_power_noreg+0x168/0x2b4
[    1.436655] Modules linked in:
[    1.436662] CPU: 2 PID: 69 Comm: kworker/u8:1 Tainted: G        W         5.15.0-rc1+ #137
[    1.436669] Hardware name: Thundercomm TurboX CM2290 (DT)
[    1.436674] Workqueue: events_unbound async_run_entry_fn
[    1.436685] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[    1.436692] pc : sdhci_set_power_noreg+0x168/0x2b4
[    1.436698] lr : sdhci_set_power_noreg+0x168/0x2b4
[    1.436703] sp : ffff800010803a60
[    1.436705] x29: ffff800010803a60 x28: ffff6a9102465f00 x27: ffff6a9101720a70
[    1.436715] x26: ffff6a91014de1c0 x25: ffff6a91014de010 x24: ffff6a91016af280
[    1.436724] x23: ffffaf7b1b276640 x22: 0000000000000000 x21: ffff6a9101720000
[    1.436733] x20: ffff6a9101720370 x19: ffff6a9101720580 x18: 0000000000000020
[    1.436743] x17: 0000000000000000 x16: 0000000000000004 x15: ffffffffffffffff
[    1.436751] x14: 0000000000000000 x13: 00000000fffffffd x12: ffffaf7b1b84b0bc
[    1.436760] x11: ffffaf7b1b720d10 x10: 000000000000000a x9 : ffff800010803a60
[    1.436769] x8 : 000000000000000a x7 : 000000000000000f x6 : 00000000fffff159
[    1.436778] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 00000000ffffffff
[    1.436787] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff6a9101718d80
[    1.436797] Call trace:
[    1.436800]  sdhci_set_power_noreg+0x168/0x2b4
[    1.436805]  sdhci_set_ios+0xa0/0x7fc
[    1.436811]  mmc_power_up.part.0+0xc4/0x164
[    1.436818]  mmc_start_host+0xa0/0xb0
[    1.436824]  mmc_add_host+0x60/0x90
[    1.436830]  __sdhci_add_host+0x174/0x330
[    1.436836]  sdhci_msm_probe+0x7c0/0x920
[    1.436842]  platform_probe+0x68/0xe0
[    1.436850]  really_probe.part.0+0x9c/0x31c
[    1.436857]  __driver_probe_device+0x98/0x144
[    1.436863]  driver_probe_device+0xc8/0x15c
[    1.436869]  __device_attach_driver+0xb4/0x120
[    1.436875]  bus_for_each_drv+0x78/0xd0
[    1.436881]  __device_attach_async_helper+0xac/0xd0
[    1.436888]  async_run_entry_fn+0x34/0x110
[    1.436895]  process_one_work+0x1d0/0x354
[    1.436903]  worker_thread+0x13c/0x470
[    1.436910]  kthread+0x150/0x160
[    1.436915]  ret_from_fork+0x10/0x20
[    1.436923] ---[ end trace fcfac44cb045c3a8 ]---

Fix the issue by mapping MMC_VDD_35_36 (and MMC_VDD_34_35) to
SDHCI_POWER_330 as well.

Signed-off-by: Shawn Guo <shawn.guo@linaro.org>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: stable@vger.kernel.org
Link: https://lore.kernel.org/r/20211004024935.15326-1-shawn.guo@linaro.org
Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
popcornmix pushed a commit that referenced this issue Nov 5, 2021
commit 4217d07 upstream.

On Thundercomm TurboX CM2290, the eMMC OCR reports vdd = 23 (3.5 ~ 3.6 V),
which is being treated as an invalid value by sdhci_set_power_noreg().
And thus eMMC is totally broken on the platform.

[    1.436599] ------------[ cut here ]------------
[    1.436606] mmc0: Invalid vdd 0x17
[    1.436640] WARNING: CPU: 2 PID: 69 at drivers/mmc/host/sdhci.c:2048 sdhci_set_power_noreg+0x168/0x2b4
[    1.436655] Modules linked in:
[    1.436662] CPU: 2 PID: 69 Comm: kworker/u8:1 Tainted: G        W         5.15.0-rc1+ #137
[    1.436669] Hardware name: Thundercomm TurboX CM2290 (DT)
[    1.436674] Workqueue: events_unbound async_run_entry_fn
[    1.436685] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[    1.436692] pc : sdhci_set_power_noreg+0x168/0x2b4
[    1.436698] lr : sdhci_set_power_noreg+0x168/0x2b4
[    1.436703] sp : ffff800010803a60
[    1.436705] x29: ffff800010803a60 x28: ffff6a9102465f00 x27: ffff6a9101720a70
[    1.436715] x26: ffff6a91014de1c0 x25: ffff6a91014de010 x24: ffff6a91016af280
[    1.436724] x23: ffffaf7b1b276640 x22: 0000000000000000 x21: ffff6a9101720000
[    1.436733] x20: ffff6a9101720370 x19: ffff6a9101720580 x18: 0000000000000020
[    1.436743] x17: 0000000000000000 x16: 0000000000000004 x15: ffffffffffffffff
[    1.436751] x14: 0000000000000000 x13: 00000000fffffffd x12: ffffaf7b1b84b0bc
[    1.436760] x11: ffffaf7b1b720d10 x10: 000000000000000a x9 : ffff800010803a60
[    1.436769] x8 : 000000000000000a x7 : 000000000000000f x6 : 00000000fffff159
[    1.436778] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 00000000ffffffff
[    1.436787] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff6a9101718d80
[    1.436797] Call trace:
[    1.436800]  sdhci_set_power_noreg+0x168/0x2b4
[    1.436805]  sdhci_set_ios+0xa0/0x7fc
[    1.436811]  mmc_power_up.part.0+0xc4/0x164
[    1.436818]  mmc_start_host+0xa0/0xb0
[    1.436824]  mmc_add_host+0x60/0x90
[    1.436830]  __sdhci_add_host+0x174/0x330
[    1.436836]  sdhci_msm_probe+0x7c0/0x920
[    1.436842]  platform_probe+0x68/0xe0
[    1.436850]  really_probe.part.0+0x9c/0x31c
[    1.436857]  __driver_probe_device+0x98/0x144
[    1.436863]  driver_probe_device+0xc8/0x15c
[    1.436869]  __device_attach_driver+0xb4/0x120
[    1.436875]  bus_for_each_drv+0x78/0xd0
[    1.436881]  __device_attach_async_helper+0xac/0xd0
[    1.436888]  async_run_entry_fn+0x34/0x110
[    1.436895]  process_one_work+0x1d0/0x354
[    1.436903]  worker_thread+0x13c/0x470
[    1.436910]  kthread+0x150/0x160
[    1.436915]  ret_from_fork+0x10/0x20
[    1.436923] ---[ end trace fcfac44cb045c3a8 ]---

Fix the issue by mapping MMC_VDD_35_36 (and MMC_VDD_34_35) to
SDHCI_POWER_330 as well.

Signed-off-by: Shawn Guo <shawn.guo@linaro.org>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: stable@vger.kernel.org
Link: https://lore.kernel.org/r/20211004024935.15326-1-shawn.guo@linaro.org
Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
popcornmix pushed a commit that referenced this issue Nov 8, 2021
commit 4217d07 upstream.

On Thundercomm TurboX CM2290, the eMMC OCR reports vdd = 23 (3.5 ~ 3.6 V),
which is being treated as an invalid value by sdhci_set_power_noreg().
And thus eMMC is totally broken on the platform.

[    1.436599] ------------[ cut here ]------------
[    1.436606] mmc0: Invalid vdd 0x17
[    1.436640] WARNING: CPU: 2 PID: 69 at drivers/mmc/host/sdhci.c:2048 sdhci_set_power_noreg+0x168/0x2b4
[    1.436655] Modules linked in:
[    1.436662] CPU: 2 PID: 69 Comm: kworker/u8:1 Tainted: G        W         5.15.0-rc1+ #137
[    1.436669] Hardware name: Thundercomm TurboX CM2290 (DT)
[    1.436674] Workqueue: events_unbound async_run_entry_fn
[    1.436685] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[    1.436692] pc : sdhci_set_power_noreg+0x168/0x2b4
[    1.436698] lr : sdhci_set_power_noreg+0x168/0x2b4
[    1.436703] sp : ffff800010803a60
[    1.436705] x29: ffff800010803a60 x28: ffff6a9102465f00 x27: ffff6a9101720a70
[    1.436715] x26: ffff6a91014de1c0 x25: ffff6a91014de010 x24: ffff6a91016af280
[    1.436724] x23: ffffaf7b1b276640 x22: 0000000000000000 x21: ffff6a9101720000
[    1.436733] x20: ffff6a9101720370 x19: ffff6a9101720580 x18: 0000000000000020
[    1.436743] x17: 0000000000000000 x16: 0000000000000004 x15: ffffffffffffffff
[    1.436751] x14: 0000000000000000 x13: 00000000fffffffd x12: ffffaf7b1b84b0bc
[    1.436760] x11: ffffaf7b1b720d10 x10: 000000000000000a x9 : ffff800010803a60
[    1.436769] x8 : 000000000000000a x7 : 000000000000000f x6 : 00000000fffff159
[    1.436778] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 00000000ffffffff
[    1.436787] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff6a9101718d80
[    1.436797] Call trace:
[    1.436800]  sdhci_set_power_noreg+0x168/0x2b4
[    1.436805]  sdhci_set_ios+0xa0/0x7fc
[    1.436811]  mmc_power_up.part.0+0xc4/0x164
[    1.436818]  mmc_start_host+0xa0/0xb0
[    1.436824]  mmc_add_host+0x60/0x90
[    1.436830]  __sdhci_add_host+0x174/0x330
[    1.436836]  sdhci_msm_probe+0x7c0/0x920
[    1.436842]  platform_probe+0x68/0xe0
[    1.436850]  really_probe.part.0+0x9c/0x31c
[    1.436857]  __driver_probe_device+0x98/0x144
[    1.436863]  driver_probe_device+0xc8/0x15c
[    1.436869]  __device_attach_driver+0xb4/0x120
[    1.436875]  bus_for_each_drv+0x78/0xd0
[    1.436881]  __device_attach_async_helper+0xac/0xd0
[    1.436888]  async_run_entry_fn+0x34/0x110
[    1.436895]  process_one_work+0x1d0/0x354
[    1.436903]  worker_thread+0x13c/0x470
[    1.436910]  kthread+0x150/0x160
[    1.436915]  ret_from_fork+0x10/0x20
[    1.436923] ---[ end trace fcfac44cb045c3a8 ]---

Fix the issue by mapping MMC_VDD_35_36 (and MMC_VDD_34_35) to
SDHCI_POWER_330 as well.

Signed-off-by: Shawn Guo <shawn.guo@linaro.org>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: stable@vger.kernel.org
Link: https://lore.kernel.org/r/20211004024935.15326-1-shawn.guo@linaro.org
Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
nguyenanhgiau pushed a commit to nguyenanhgiau/linux that referenced this issue Jan 5, 2022
commit 4217d07 upstream.

On Thundercomm TurboX CM2290, the eMMC OCR reports vdd = 23 (3.5 ~ 3.6 V),
which is being treated as an invalid value by sdhci_set_power_noreg().
And thus eMMC is totally broken on the platform.

[    1.436599] ------------[ cut here ]------------
[    1.436606] mmc0: Invalid vdd 0x17
[    1.436640] WARNING: CPU: 2 PID: 69 at drivers/mmc/host/sdhci.c:2048 sdhci_set_power_noreg+0x168/0x2b4
[    1.436655] Modules linked in:
[    1.436662] CPU: 2 PID: 69 Comm: kworker/u8:1 Tainted: G        W         5.15.0-rc1+ raspberrypi#137
[    1.436669] Hardware name: Thundercomm TurboX CM2290 (DT)
[    1.436674] Workqueue: events_unbound async_run_entry_fn
[    1.436685] pstate: 60000005 (nZCv daif -PAN -UAO -TCO -DIT -SSBS BTYPE=--)
[    1.436692] pc : sdhci_set_power_noreg+0x168/0x2b4
[    1.436698] lr : sdhci_set_power_noreg+0x168/0x2b4
[    1.436703] sp : ffff800010803a60
[    1.436705] x29: ffff800010803a60 x28: ffff6a9102465f00 x27: ffff6a9101720a70
[    1.436715] x26: ffff6a91014de1c0 x25: ffff6a91014de010 x24: ffff6a91016af280
[    1.436724] x23: ffffaf7b1b276640 x22: 0000000000000000 x21: ffff6a9101720000
[    1.436733] x20: ffff6a9101720370 x19: ffff6a9101720580 x18: 0000000000000020
[    1.436743] x17: 0000000000000000 x16: 0000000000000004 x15: ffffffffffffffff
[    1.436751] x14: 0000000000000000 x13: 00000000fffffffd x12: ffffaf7b1b84b0bc
[    1.436760] x11: ffffaf7b1b720d10 x10: 000000000000000a x9 : ffff800010803a60
[    1.436769] x8 : 000000000000000a x7 : 000000000000000f x6 : 00000000fffff159
[    1.436778] x5 : 0000000000000000 x4 : 0000000000000000 x3 : 00000000ffffffff
[    1.436787] x2 : 0000000000000000 x1 : 0000000000000000 x0 : ffff6a9101718d80
[    1.436797] Call trace:
[    1.436800]  sdhci_set_power_noreg+0x168/0x2b4
[    1.436805]  sdhci_set_ios+0xa0/0x7fc
[    1.436811]  mmc_power_up.part.0+0xc4/0x164
[    1.436818]  mmc_start_host+0xa0/0xb0
[    1.436824]  mmc_add_host+0x60/0x90
[    1.436830]  __sdhci_add_host+0x174/0x330
[    1.436836]  sdhci_msm_probe+0x7c0/0x920
[    1.436842]  platform_probe+0x68/0xe0
[    1.436850]  really_probe.part.0+0x9c/0x31c
[    1.436857]  __driver_probe_device+0x98/0x144
[    1.436863]  driver_probe_device+0xc8/0x15c
[    1.436869]  __device_attach_driver+0xb4/0x120
[    1.436875]  bus_for_each_drv+0x78/0xd0
[    1.436881]  __device_attach_async_helper+0xac/0xd0
[    1.436888]  async_run_entry_fn+0x34/0x110
[    1.436895]  process_one_work+0x1d0/0x354
[    1.436903]  worker_thread+0x13c/0x470
[    1.436910]  kthread+0x150/0x160
[    1.436915]  ret_from_fork+0x10/0x20
[    1.436923] ---[ end trace fcfac44cb045c3a8 ]---

Fix the issue by mapping MMC_VDD_35_36 (and MMC_VDD_34_35) to
SDHCI_POWER_330 as well.

Signed-off-by: Shawn Guo <shawn.guo@linaro.org>
Acked-by: Adrian Hunter <adrian.hunter@intel.com>
Cc: stable@vger.kernel.org
Link: https://lore.kernel.org/r/20211004024935.15326-1-shawn.guo@linaro.org
Signed-off-by: Ulf Hansson <ulf.hansson@linaro.org>
Signed-off-by: Greg Kroah-Hartman <gregkh@linuxfoundation.org>
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

5 participants