VCHIQ functional test broken since 4.11rc1

[lategoodbye]

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've bisected this regression to this commit:

00a19f3e25c0c40e0ec77f52d4841d23ad269169 is the first bad commit
commit 00a19f3e25c0c40e0ec77f52d4841d23ad269169
Author: Rabin Vincent <rabinv@axis.com>
Date: Tue Nov 8 09:21:19 2016 +0100

ARM: 8627/1: avoid cache flushing in flush_dcache_page()

When the data cache is PIPT or VIPT non-aliasing, and cache operations
are broadcast by the hardware, we can always postpone the flush in
flush_dcache_page(). A similar change was done for ARM64 in commit
b5b6c9e9149d ("arm64: Avoid cache flushing in flush_dcache_page()").

Reviewed-by: Catalin Marinas <catalin.marinas@arm.com>
Signed-off-by: Rabin Vincent <rabinv@axis.com>
Signed-off-by: Russell King <rmk+kernel@arm.linux.org.uk>

It seems that staging/vc04_services/interface/vchiq_arm/vchiq_2835_arm relies on the behavior of flush_dcache_page before this patch get applied.

Here the related thread on linux-rpi-kernel.

It would be nice to get a solution which is acceptable in mainline.

[ED6E0F17]

00a19f3 depends on !cache_ops_need_broadcast() :

#if !defined(CONFIG_SMP) || __LINUX_ARM_ARCH__ >= 7
#define cache_ops_need_broadcast()      0

It seems sensible to revert the regression for armv6 only.

[lategoodbye]

@ED6E0F17 Could you please explain why this is the right solution? Regarding to Russell's explanation the issue must be in the driver. Playing with fundamental ARM parts could break other platforms.

Btw i already found a workaround by calling flush_cache_all() after get_user_pages().

[ED6E0F17]

I forgot to ask if this is broken on Armv7, but I was working with RMK`s comment "What I'm willing to do is to temporarily drop the offending patch".

The last thing that I considered is that the upstream patch might be broken, and reverting it is best avoided if you have another solution.

[pelwell]

I'm looking through this now, and the failure mechanism isn't obvious. I haven't got it to fail on ARMv7, but that is probably because we define CONFIG_SMP on those platforms.

[lategoodbye]

@ED6E0F17 I must confess that didn't test it on ARMv7 or ARMv8.

RMK's suggested to enable debugging for vchiq. After setting all debugfs entries to loglevel info the dmesg is flooded. So i'm skeptical that will helps.

[pelwell]

I've been looking for non-standard behaviour by the driver. It's using the standard DMA map/unmap functions now, and the only questionable code I've seen is using memcpy to copy in the read data to partial cache lines. The destination is a user page, and the context may be the application thread or it may be a kernel thread...

[lategoodbye]

Can you point me to the line?
Does it mean it could be the problem?

[pelwell]

I was thinking of this line and this one, but I haven't identified the mechanism yet.

[lategoodbye]

I tested ARMv7 today and got a NULL pointer dereference in free_pagelist. So i better fix this before.

[lategoodbye]

@ED6E0F17 Thanks for extending vchiq_test, i will update ASAP.

[lategoodbye]

Okay, here are the results for mainline tree + bcm2836 dtb (vchiq node patched) + multi_v7_defconfig on Raspberry Pi 2 :

df044eb -> don't build on v7 because of implicite declaration of v7_dma_map_area
cf9caf1 -> NULL pointer dereference in memcpy of free_pagelist

So i switched to raspberry pi tree + bcm2836 dtb (vchiq node patched) + multi_v7_defconfig on Raspberry Pi 2 :

525571c -> vchiq_test hang, unable to terminate program

Here an strace until the hang (unfortunately not always the same position):

pi@raspberrypi:~$ strace -f vchiq_test -f 1
execve("/usr/bin/vchiq_test", ["vchiq_test", "-f", "1"], [/* 13 vars */]) = 0
brk(0)                                  = 0x3a000
uname({sys="Linux", node="raspberrypi", ...}) = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
mmap2(NULL, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f57000
access("/etc/ld.so.preload", R_OK)      = 0
open("/etc/ld.so.preload", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=42, ...}) = 0
mmap2(NULL, 42, PROT_READ|PROT_WRITE, MAP_PRIVATE, 3, 0) = 0xb6f56000
close(3)                                = 0
open("/usr/lib/arm-linux-gnueabihf/libarmmem.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0h\5\0\0004\0\0\0"..., 512) = 512
lseek(3, 17960, SEEK_SET)               = 17960
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 960) = 960
lseek(3, 17696, SEEK_SET)               = 17696
read(3, "A.\0\0\0aeabi\0\1$\0\0\0\0056\0\6\6\10\1\t\1\n\3\f\1\22\4\24"..., 47) = 47
fstat64(3, {st_mode=S_IFREG|0644, st_size=18920, ...}) = 0
mmap2(NULL, 83236, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6f15000
mprotect(0xb6f1a000, 61440, PROT_NONE)  = 0
mmap2(0xb6f29000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x4000) = 0xb6f29000
mprotect(0xbea85000, 4096, PROT_READ|PROT_WRITE|PROT_EXEC|PROT_GROWSDOWN) = 0
close(3)                                = 0
munmap(0xb6f56000, 42)                  = 0
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
fstat64(3, {st_mode=S_IFREG|0644, st_size=24350, ...}) = 0
mmap2(NULL, 24350, PROT_READ, MAP_PRIVATE, 3, 0) = 0xb6f51000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/opt/vc/lib/libvchiq_arm.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0(\26\0\0004\0\0\0"..., 512) = 512
lseek(3, 29248, SEEK_SET)               = 29248
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1040) = 1040
lseek(3, 21226, SEEK_SET)               = 21226
read(3, "A;\0\0\0aeabi\0\0011\0\0\0\5ARM1176JZF-S\0\6\7"..., 60) = 60
fstat64(3, {st_mode=S_IFREG|0644, st_size=30288, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f50000
mmap2(NULL, 88456, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6eff000
mprotect(0xb6f05000, 61440, PROT_NONE)  = 0
mmap2(0xb6f14000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0xb6f14000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/opt/vc/lib/libvcos.so", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\234*\0\0004\0\0\0"..., 512) = 512
lseek(3, 171748, SEEK_SET)              = 171748
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1360) = 1360
lseek(3, 37806, SEEK_SET)               = 37806
read(3, "A;\0\0\0aeabi\0\0011\0\0\0\5ARM1176JZF-S\0\6\7"..., 60) = 60
fstat64(3, {st_mode=S_IFREG|0644, st_size=173108, ...}) = 0
mmap2(NULL, 105624, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6ee5000
mprotect(0xb6eee000, 65536, PROT_NONE)  = 0
mmap2(0xb6efe000, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x9000) = 0xb6efe000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/arm-linux-gnueabihf/libpthread.so.0", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0lY\0\0004\0\0\0"..., 512) = 512
lseek(3, 120788, SEEK_SET)              = 120788
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1520) = 1520
lseek(3, 86420, SEEK_SET)               = 86420
read(3, "A0\0\0\0aeabi\0\1&\0\0\0\0056\0\6\6\10\1\t\1\n\2\22\4\23\1\24"..., 49) = 49
fstat64(3, {st_mode=S_IFREG|0755, st_size=122308, ...}) = 0
mmap2(NULL, 160316, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6ebd000
mprotect(0xb6ed1000, 65536, PROT_NONE)  = 0
mmap2(0xb6ee1000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x14000) = 0xb6ee1000
mmap2(0xb6ee3000, 4668, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6ee3000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/arm-linux-gnueabihf/libdl.so.2", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0\220\t\0\0004\0\0\0"..., 512) = 512
lseek(3, 8660, SEEK_SET)                = 8660
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1160) = 1160
lseek(3, 8328, SEEK_SET)                = 8328
read(3, "A0\0\0\0aeabi\0\1&\0\0\0\0056\0\6\6\10\1\t\1\n\2\22\4\23\1\24"..., 49) = 49
fstat64(3, {st_mode=S_IFREG|0644, st_size=9820, ...}) = 0
mmap2(NULL, 73912, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6eaa000
mprotect(0xb6eac000, 61440, PROT_NONE)  = 0
mmap2(0xb6ebb000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x1000) = 0xb6ebb000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/arm-linux-gnueabihf/librt.so.1", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\3\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0000\30\0\0004\0\0\0"..., 512) = 512
lseek(3, 25352, SEEK_SET)               = 25352
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 1320) = 1320
lseek(3, 24964, SEEK_SET)               = 24964
read(3, "A0\0\0\0aeabi\0\1&\0\0\0\0056\0\6\6\10\1\t\1\n\2\22\4\23\1\24"..., 49) = 49
fstat64(3, {st_mode=S_IFREG|0644, st_size=26672, ...}) = 0
mmap2(NULL, 90684, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6e93000
mprotect(0xb6e99000, 61440, PROT_NONE)  = 0
mmap2(0xb6ea8000, 8192, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x5000) = 0xb6ea8000
close(3)                                = 0
access("/etc/ld.so.nohwcap", F_OK)      = -1 ENOENT (No such file or directory)
open("/lib/arm-linux-gnueabihf/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\1\1\1\0\0\0\0\0\0\0\0\0\3\0(\0\1\0\0\0L\204\1\0004\0\0\0"..., 512) = 512
lseek(3, 1239936, SEEK_SET)             = 1239936
read(3, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 2840) = 2840
lseek(3, 1236500, SEEK_SET)             = 1236500
read(3, "A.\0\0\0aeabi\0\1$\0\0\0\0056\0\6\6\10\1\t\1\n\2\22\4\23\1\24"..., 47) = 47
fstat64(3, {st_mode=S_IFREG|0755, st_size=1242776, ...}) = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f4f000
mmap2(NULL, 1312152, PROT_READ|PROT_EXEC, MAP_PRIVATE|MAP_DENYWRITE, 3, 0) = 0xb6d52000
mprotect(0xb6e7d000, 65536, PROT_NONE)  = 0
mmap2(0xb6e8d000, 12288, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_DENYWRITE, 3, 0x12b000) = 0xb6e8d000
mmap2(0xb6e90000, 9624, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_FIXED|MAP_ANONYMOUS, -1, 0) = 0xb6e90000
close(3)                                = 0
mmap2(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f4e000
set_tls(0xb6f4e4c0, 0xb6f4eba8, 0xb6f5a050, 0xb6f4e4c0, 0xb6f5a050) = 0
mprotect(0xb6e8d000, 8192, PROT_READ)   = 0
mprotect(0xb6ee1000, 4096, PROT_READ)   = 0
mprotect(0xb6ea8000, 4096, PROT_READ)   = 0
mprotect(0xb6ebb000, 4096, PROT_READ)   = 0
mprotect(0xb6f15000, 20480, PROT_READ|PROT_WRITE) = 0
mprotect(0xb6f15000, 20480, PROT_READ|PROT_EXEC) = 0
cacheflush(0xb6f15000, 0xb6f1a000, 0, 0x15, 0xbea85940) = 0
mprotect(0xb6f59000, 4096, PROT_READ)   = 0
munmap(0xb6f51000, 24350)               = 0
set_tid_address(0xb6f4e068)             = 510
set_robust_list(0xb6f4e070, 12)         = 0
rt_sigaction(SIGRTMIN, {0xb6ec2434, [], SA_RESTORER|SA_SIGINFO, 0xb6d811a0}, NULL, 8) = 0
rt_sigaction(SIGRT_1, {0xb6ec22d8, [], SA_RESTORER|SA_RESTART|SA_SIGINFO, 0xb6d811a0}, NULL, 8) = 0
rt_sigprocmask(SIG_UNBLOCK, [RTMIN4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0xb6f56000
write(1, "Functional test - iters:1\n", 26Functional test - iters:1
) = 26
write(1, "======== iteration 1 ========\n", 30======== iteration 1 ========
) = 30
open("/dev/vchiq", O_RDWR|O_LARGEFILE)  = 3
ioctl(3, 0xc008c40a, 0xbea85b5c)        = 0
ioctl(3, 0xc410, 0x8)                   = 0
ioctl(3, 0xc008c40a, 0xbea85b88)        = 0
ioctl(3, 0xc008c40a, 0xbea85b88)        = -1 EINVAL (Invalid argument)
ioctl(3, 0xc008c40a, 0xbea85b88)        = 0
ioctl(3, 0xc01cc402, 0xbea85b24)        = 0
ioctl(3, 0xc01cc402, 0xbea85b24)        = 0
ioctl(3, 0x400cc40e, 0xbea85b84)        = 0
ioctl(3, 0x400cc40e, 0xbea85b84)        = 0
ioctl(3, 0x400cc40e, 0xbea85b84)        = -1 EIO (Input/output error)
ioctl(3, 0xc403, 0x1000)                = 0
ioctl(3, 0xc403, 0x2001)                = 0
ioctl(3, 0xc01cc402, 0xbea85b24)        = 0
ioctl(3, 0xc403, 0x3000)                = 0
close(3)                                = 0
open("/dev/vchiq", O_RDWR|O_LARGEFILE)  = 3
ioctl(3, 0xc008c40a, 0xbea85b5c)        = 0
ioctl(3, 0xc410, 0x8)                   = 0
ioctl(3, 0xc01cc402, 0xbea85b24)        = -1 ENOTCONN (Transport endpoint is not connected)
ioctl(3, 0xc400, 0)                     = 0
mmap2(NULL, 8388608, PROT_READ|PROT_WRITE|PROT_EXEC, MAP_PRIVATE|MAP_ANONYMOUS|MAP_STACK, -1, 0) = 0xb6552000
brk(0)                                  = 0x3a000
brk(0x5b000)                            = 0x5b000
mprotect(0xb6552000, 4096, PROT_NONE)   = 0
clone(Process 512 attached
child_stack=0xb6d50f98, flags=CLONE_VM|CLONE_FS|CLONE_FILES|CLONE_SIGHAND|CLONE_THREAD|CLONE_SYSVSEM|CLONE_SETTLS|CLONE_PARENT_SETTID|CLONE_CHILD_CLEARTID, parent_tidptr=0xb6d514c8, tls=0xb6d51920, child_tidptr=0xb6d514c8) = 512
[pid   512] set_robust_list(0xb6d514d0, 12 <unfinished ...>
[pid   510] ioctl(3, 0xc01cc402 <unfinished ...>
[pid   512] <... set_robust_list resumed> ) = 0
[pid   512] prctl(PR_SET_NAME, 0xb6f143b0, 0, 0, 0) = 0
[pid   512] mmap2(NULL, 2097152, PROT_NONE, MAP_PRIVATE|MAP_ANONYMOUS|MAP_NORESERVE, -1, 0 <unfinished ...>
[pid   510] <... ioctl resumed> , 0xbea85b24) = -1 EIO (Input/output error)
[pid   512] <... mmap2 resumed> )       = 0xb6352000
[pid   510] ioctl(3, 0xc01cc402 <unfinished ...>
[pid   512] munmap(0xb6352000, 712704)  = 0
[pid   512] munmap(0xb6500000, 335872 <unfinished ...>
[pid   510] <... ioctl resumed> , 0xbea85b24) = -1 EIO (Input/output error)
[pid   512] <... munmap resumed> )      = 0
[pid   510] ioctl(3, 0xc01cc402 <unfinished ...>
[pid   512] mprotect(0xb6400000, 139264, PROT_READ|PROT_WRITE) = 0
[pid   510] <... ioctl resumed> , 0xbea85b24) = -1 EIO (Input/output error)
[pid   512] ioctl(3, 0xc014c407 <unfinished ...>
[pid   510] ioctl(3, 0xc01cc402, 0xbea85b24) = 0
[pid   510] ioctl(3, 0xc01cc402, 0xbea85b24) = -1 EIO (Input/output error)
[pid   510] ioctl(3, 0xc01cc402, 0xbea85b24) = 0
[pid   510] ioctl(3, 0xc01cc402, 0xbea85b24) = -1 EIO (Input/output error)
[pid   510] ioctl(3, 0xc403 <unfinished ...>
[pid   512] <... ioctl resumed> , 0xb6d50d6c) = 1
[pid   512] ioctl(3, 0xc411 <unfinished ...>
[pid   510] <... ioctl resumed> , 0xa002) = 0
[pid   512] <... ioctl resumed> , 0xa002) = 0
[pid   510] ioctl(3, 0xc01cc402 <unfinished ...>
[pid   512] ioctl(3, 0xc014c407 <unfinished ...>
[pid   510] <... ioctl resumed> , 0xbea85b24) = 0
[pid   510] ioctl(3, 0x400cc404, 0xbea85b7c) = 0
[pid   512] <... ioctl resumed> , 0xb6d50d6c) = 1
[pid   510] ioctl(3, 0xc014c405 <unfinished ...>
[pid   512] ioctl(3, 0xc014c407 <unfinished ...>
[pid   510] <... ioctl resumed> , 0xbea85b74) = 0
[pid   510] ioctl(3, 0xc014c405, 0xbea85b74) = 0
[pid   510] futex(0x2e4e4, FUTEX_WAIT_PRIVATE, 0, NULL

[pelwell]

Returning to the initial bug report, I think the problem may lie in this commit: cf9caf1

The loop calling sg_set_page sets up a scatterlist comprising whole pages, which looks dangerous when you follow it up with DMA_FROM_DEVICE cache maintenance (invalidate).

Any comments, @Electron752?

[ED6E0F17]

There is an issue with corrupt messages on Linux 4.5 and 4.9 when the "lazy cache flushing" patch is backported.

The issue with the test stalling seems to be new to Linux 4.11, and I sometimes see it running slowly on Arm v7, although I cannot make it fail on Pi2.

[pelwell]

See #1987 for a fix for the corruption.