[Bug] VCHIQ functional test broken

Tue Apr 11 11:10:05 PDT 2017

Hi,

recently i found that vchiq_test -f doesn't work anymore with current mainline (4.11-rc6) and linux-next (20170404) on my Raspberry Pi Zero. The issue is always reproducible, but the error behavior isn't deterministic. Sometimes vchiq_test hangs and sometimes i get an error message from vchiq_test like this (but never errors from the kernel):

$ vchiq_test -f 10
Functional test - iters:10
======== iteration 1 ========
vchiq_test: 1502: expected callback reason VCHIQ_MESSAGE_AVAILABLE, got 1
vchiq_test: 1524: expected callback reason VCHIQ_BULK_TRANSMIT_DONE, got 5
vchiq_test: 863: func_error != 0

I didn't had the time to bisect, but at least 4.10 is safe.

Here are some relevant config parameters:

CONFIG_CMA=n
CONFIG_BCM2835_MBOX=y
CONFIG_RASPBERRYPI_FIRMWARE=y
CONFIG_BCM2835_VCHIQ=y
CONFIG_DMA_ENGINE=y
CONFIG_DMA_VIRTUAL_CHANNELS=y
CONFIG_DMA_OF=y
CONFIG_DMA_BCM2835=y

Here are the boot messages which might be helpful:

[    0.000000] Booting Linux on physical CPU 0x0
[    0.000000] Linux version 4.11.0-rc6+ (user at Raspberry) (gcc version 4.7.1 20120402 (prerelease) (crosstool-NG 1.15.2) ) #1 Mon Apr 10 19:37:15 UTC 2017
[    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] OF: fdt: Machine model: Raspberry Pi Zero
[    0.000000] Memory policy: Data cache writeback
[    0.000000] CPU: All CPU(s) started in SVC mode.
[    0.000000] Built 1 zonelists in Zone order, mobility grouping on.  Total pages: 113792
[    0.000000] Kernel command line: console=tty0 console=ttyAMA0 root=/dev/mmcblk0p2 rootwait no_console_suspend
[    0.000000] PID hash table entries: 2048 (order: 1, 8192 bytes)
[    0.000000] Dentry cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Inode-cache hash table entries: 32768 (order: 5, 131072 bytes)
[    0.000000] Memory: 442060K/458752K available (7168K kernel code, 513K rwdata, 1640K rodata, 1024K init, 804K bss, 16692K reserved, 0K cma-reserved)
[    0.000000] Virtual kernel memory layout:
[    0.000000]     vector  : 0xffff0000 - 0xffff1000   (   4 kB)
[    0.000000]     fixmap  : 0xffc00000 - 0xfff00000   (3072 kB)
[    0.000000]     vmalloc : 0xdc800000 - 0xff800000   ( 560 MB)
[    0.000000]     lowmem  : 0xc0000000 - 0xdc000000   ( 448 MB)
[    0.000000]       .text : 0xc0008000 - 0xc0800000   (8160 kB)
[    0.000000]       .init : 0xc0b00000 - 0xc0c00000   (1024 kB)
[    0.000000]       .data : 0xc0c00000 - 0xc0c806a0   ( 514 kB)
[    0.000000]        .bss : 0xc0c82000 - 0xc0d4b234   ( 805 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=1, Nodes=1
[    0.000000] NR_IRQS:16 nr_irqs:16 16
[    0.000029] sched_clock: 32 bits at 1000kHz, resolution 1000ns, wraps every 2147483647500ns
[    0.000075] clocksource: timer: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 1911260446275 ns
[    0.000163] bcm2835: system timer (irq = 27)
[    0.000778] Console: colour dummy device 80x30
[    0.001769] console [tty0] enabled
[    0.001851] Calibrating delay loop... 697.95 BogoMIPS (lpj=3489792)
[    0.060399] pid_max: default: 32768 minimum: 301
[    0.060848] Mount-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.060936] Mountpoint-cache hash table entries: 1024 (order: 0, 4096 bytes)
[    0.062057] CPU: Testing write buffer coherency: ok
[    0.062200] ftrace: allocating 23526 entries in 69 pages
[    0.206069] Setting up static identity map for 0x100000 - 0x10004c
[    0.210296] devtmpfs: initialized
[    0.216761] VFP support v0.3: implementor 41 architecture 1 part 20 variant b rev 5
[    0.217328] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.217468] futex hash table entries: 256 (order: -1, 3072 bytes)
[    0.217762] pinctrl core: initialized pinctrl subsystem
[    0.218514] NET: Registered protocol family 16
[    0.219155] DMA: preallocated 256 KiB pool for atomic coherent allocations
[    0.224195] No ATAGs?
[    0.224232] hw-breakpoint: found 6 breakpoint and 1 watchpoint registers.
[    0.224370] hw-breakpoint: maximum watchpoint size is 4 bytes.
[    0.224708] Serial: AMBA PL011 UART driver
[    0.248332] SCSI subsystem initialized
[    0.248864] usbcore: registered new interface driver usbfs
[    0.249018] usbcore: registered new interface driver hub
[    0.249238] usbcore: registered new device driver usb
[    0.249723] Advanced Linux Sound Architecture Driver Initialized.
[    0.252218] clocksource: Switched to clocksource timer
[    0.338568] simple-framebuffer 1eaf0000.framebuffer: framebuffer at 0x1eaf0000, 0x10a800 bytes, mapped to 0xdca00000
[    0.338731] simple-framebuffer 1eaf0000.framebuffer: format=a8r8g8b8, mode=656x416x32, linelength=2624
[    0.349965] Console: switching to colour frame buffer device 82x26
[    0.367361] simple-framebuffer 1eaf0000.framebuffer: fb0: simplefb registered!
[    0.395200] NET: Registered protocol family 2
[    0.403891] TCP established hash table entries: 4096 (order: 2, 16384 bytes)
[    0.411532] TCP bind hash table entries: 4096 (order: 2, 16384 bytes)
[    0.419070] TCP: Hash tables configured (established 4096 bind 4096)
[    0.426581] UDP hash table entries: 256 (order: 0, 4096 bytes)
[    0.433901] UDP-Lite hash table entries: 256 (order: 0, 4096 bytes)
[    0.441314] NET: Registered protocol family 1
[    0.449206] RPC: Registered named UNIX socket transport module.
[    0.456502] RPC: Registered udp transport module.
[    0.463542] RPC: Registered tcp transport module.
[    0.470264] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.478111] hw perfevents: enabled with armv6_1176 PMU driver, 3 counters available
[    0.494421] workingset: timestamp_bits=30 max_order=17 bucket_order=0
[    0.519261] Installing knfsd (copyright (C) 1996 okir at monad.swb.de).
[    0.535279] jitterentropy: Initialization failed with host not compliant with requirements: 2
[    0.550868] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 252)
[    0.566318] io scheduler noop registered
[    0.573945] io scheduler deadline registered
[    0.581855] io scheduler cfq registered (default)
[    0.589130] io scheduler mq-deadline registered
[    0.610940] bcm2835-rng 20104000.rng: hwrng registered
[    0.621900] libphy: Fixed MDIO Bus: probed
[    0.629186] usbcore: registered new interface driver zd1211rw
[    0.636172] usbcore: registered new interface driver asix
[    0.642799] usbcore: registered new interface driver ax88179_178a
[    0.649191] usbcore: registered new interface driver cdc_ether
[    0.655420] usbcore: registered new interface driver smsc95xx
[    0.661391] usbcore: registered new interface driver net1080
[    0.667217] usbcore: registered new interface driver cdc_subset
[    0.672855] usbcore: registered new interface driver zaurus
[    0.678339] usbcore: registered new interface driver cdc_ncm
[    0.684270] usbcore: registered new interface driver usb-storage
[    0.690266] mousedev: PS/2 mouse device common for all mice
[    0.696065] i2c /dev entries driver
[    0.703335] i2c-bcm2835 20805000.i2c: Could not read clock-frequency property
[    0.710174] bcm2835-wdt 20100000.watchdog: Broadcom BCM2835 watchdog timer
[    0.716073] sdhci: Secure Digital Host Controller Interface driver
[    0.721295] sdhci: Copyright(c) Pierre Ossman
[    0.726359] sdhci-pltfm: SDHCI platform and OF driver helper
[    0.792289] mmc0: SDHCI controller on 20300000.sdhci [20300000.sdhci] using PIO
[    0.798461] ledtrig-cpu: registered to indicate activity on CPUs
[    0.807996] usbcore: registered new interface driver usbhid
[    0.813141] usbhid: USB HID core driver
[    0.819160] bcm2835-mbox 2000b880.mailbox: mailbox enabled
[    0.830500] oprofile: using arm/armv6
[    0.837842] NET: Registered protocol family 10
[    0.845172] Segment Routing with IPv6
[    0.850499] sit: IPv6, IPv4 and MPLS over IPv4 tunneling driver
[    0.857291] NET: Registered protocol family 17
[    0.870787] 20201000.serial: ttyAMA0 at MMIO 0x20201000 (irq = 81, base_baud = 0) is a PL011 rev2
[    0.909145] mmc0: new high speed SDHC card at address 1234
[    0.918293] mmcblk0: mmc0:1234 SA32G 29.3 GiB
[    0.924939]  mmcblk0: p1 p2
[    1.538951] console [ttyAMA0] enabled
[    1.551460] raspberrypi-firmware soc:firmware: Attached to firmware from 2017-02-13 17:40
[    1.573103] vchiq: vchiq_init_state: slot_zero = dc86e000, is_master = 0
[    1.591848] vc4-drm soc:gpu: bound 20902000.hdmi (ops vc4_hdmi_ops)
[    1.605777] vc4-drm soc:gpu: bound 20806000.vec (ops vc4_vec_ops)
[    1.619213] vc4-drm soc:gpu: bound 20400000.hvs (ops vc4_hvs_ops)
[    1.632673] vc4-drm soc:gpu: bound 20206000.pixelvalve (ops vc4_crtc_ops)
[    1.646804] vc4-drm soc:gpu: bound 20207000.pixelvalve (ops vc4_crtc_ops)
[    1.660685] vc4-drm soc:gpu: bound 20807000.pixelvalve (ops vc4_crtc_ops)
[    1.674118] vc4-drm soc:gpu: bound 20c00000.v3d (ops vc4_v3d_ops)
[    1.686565] fb: switching to vc4drmfb from simple
[    1.697683] Console: switching to colour dummy device 80x30
[    1.705521] [drm] Initialized vc4 0.0.0 20140616 for soc:gpu on minor 0
[    1.712177] [drm] Supports vblank timestamp caching Rev 2 (21.10.2013).
[    1.718889] [drm] Driver supports precise vblank timestamp query.
[    1.772490] Console: switching to colour frame buffer device 90x30
[    1.801400] vc4-drm soc:gpu: fb0:  frame buffer device
[    1.865935] dwc2 20980000.usb: DWC OTG Controller
[    1.877484] dwc2 20980000.usb: new USB bus registered, assigned bus number 1
[    1.891390] dwc2 20980000.usb: irq 33, io mem 0x20980000
[    1.905341] hub 1-0:1.0: USB hub found
[    1.915902] hub 1-0:1.0: 1 port detected
[    1.927852] ALSA device list:
[    1.937302]   No soundcards found.
[    1.947433] random: fast init done
[    1.957581] uart-pl011 20201000.serial: no DMA platform data
[    1.971656] EXT4-fs (mmcblk0p2): couldn't mount as ext3 due to feature incompatibilities
[    2.027306] EXT4-fs (mmcblk0p2): mounted filesystem with ordered data mode. Opts: (null)
[    2.048883] VFS: Mounted root (ext4 filesystem) readonly on device 179:2.
[    2.076636] devtmpfs: mounted
[    2.089497] Freeing unused kernel memory: 1024K