SPI DMA timeout when loading driver during bootup

[dmosberger]

I see the below SPI DMA timeout when the driver gets loaded automatically during bootup. What appears to be happening is that wilc_spi_init() on the first attempt to read WILC_SPI_PROTOCOL_OFFSET is triggering the timeout. If I load the driver manually after the system is booted up, this SPI DMA timeout does not occur.

Regardless of when the driver gets loaded, CRC is turned off. Is that OK or does that indicated a deeper problem?

[   11.360000] WARNING: CPU: 0 PID: 564 at drivers/spi/spi-atmel.c:1360 atmel_spi_transfer_one_message+0x594/0x944 [spi_atmel]
[   11.360000] Modules linked in: wilc_spi firmware_class tmp102 cfg80211 hwmon act8865_regulator regmap_i2c evdev pcd8544 lcd cpkadc atmel_tdes leds_pwm des_generic gpio_keys atmel_rng rng_core i2c_at91 i2c_core pwm_atmel ehci_atmel macb atmel_aes nvmem_atmel_secumod nvmem_core ehci_hcd spi_atmel atmel_sha ohci_at91 ohci_hcd usbcore usb_common
[   11.360000] CPU: 0 PID: 564 Comm: wpa_supplicant Not tainted 4.9.241+ #165
[   11.360000] Hardware name: Atmel SAMA5
[   11.360000] Backtrace:
[   11.360000] [<c010bb8c>] (dump_backtrace) from [<c010be64>] (show_stack+0x18/0x1c)
[   11.360000]  r7:00000000 r6:00000000 r5:00000009 r4:bf091068
[   11.360000] [<c010be4c>] (show_stack) from [<c0236b0c>] (dump_stack+0x20/0x28)
[   11.360000] [<c0236aec>] (dump_stack) from [<c015a484>] (__warn+0xdc/0xf8)
[   11.360000] [<c015a3a8>] (__warn) from [<c0113e2c>] (warn_slowpath_null+0x28/0x30)
[   11.360000]  r9:d08118e8 r8:d0817568 r7:cf23b258 r6:cf3fbbac r5:cf23b258 r4:cf3fbbe4
[   11.360000] [<c0113e04>] (warn_slowpath_null) from [<bf08f6c0>] (atmel_spi_transfer_one_message+0x594/0x944 [spi_atmel])
[   11.360000] [<bf08f12c>] (atmel_spi_transfer_one_message [spi_atmel]) from [<c02cea64>] (__spi_pump_messages+0x1f4/0x424)
[   11.360000]  r10:cf92d340 r9:60030013 r8:cf23b100 r7:cf3fbbac r6:00000000 r5:60030013
[   11.360000]  r4:cf23b000
[   11.360000] [<c02ce870>] (__spi_pump_messages) from [<c02d0cb4>] (__spi_sync+0x100/0x134)
[   11.360000]  r10:cf92d340 r9:60030013 r8:c02ce13c r7:cf3fbb5c r6:cf23b000 r5:cf3fbbac
[   11.360000]  r4:cf256400
[   11.360000] [<c02d0bb4>] (__spi_sync) from [<c02d0d14>] (spi_sync+0x2c/0x44)
[   11.360000]  r9:00000000 r8:cf256400 r7:cf3fbc58 r6:cf3fbc78 r5:cf3fbbac r4:cf256400
[   11.360000] [<c02d0ce8>] (spi_sync) from [<bf205578>] (wilc_spi_tx_rx+0xa0/0xc4 [wilc_spi])
[   11.360000]  r5:cf256400 r4:cf3fbbac
[   11.360000] [<bf2054d8>] (wilc_spi_tx_rx [wilc_spi]) from [<bf205a24>] (spi_cmd_complete+0x140/0x584 [wilc_spi])
[   11.360000]  r7:000000c4 r6:cf3fbd00 r5:cf256400 r4:00000005
[   11.360000] [<bf2058e4>] (spi_cmd_complete [wilc_spi]) from [<bf205f04>] (spi_internal_read+0x48/0xb0 [wilc_spi])
[   11.360000]  r10:bf20d3a5 r9:cf256400 r8:cf3fbd00 r7:00000024 r6:0000000a r5:cf256400
[   11.360000]  r4:cf92d340
[   11.360000] [<bf205ebc>] (spi_internal_read [wilc_spi]) from [<bf20674c>] (wilc_spi_init+0x54/0x17c [wilc_spi])
[   11.360000]  r10:bedffa60 r9:cf92d340 r8:cf92d340 r7:00000000 r6:cf397a80 r5:cf256400
[   11.360000]  r4:00000000
[   11.360000] [<bf2066f8>] (wilc_spi_init [wilc_spi]) from [<bf2045bc>] (wilc_wlan_init+0x78/0x2c4 [wilc_spi])
[   11.360000]  r8:bf20e34c r7:cf090000 r6:cf92d3f4 r5:cf92d340 r4:00000000
[   11.360000] [<bf204544>] (wilc_wlan_init [wilc_spi]) from [<bf1fb428>] (wilc_mac_open+0x11c/0x1004 [wilc_spi])
[   11.360000]  r8:bf20e340 r7:cf92d340 r6:bf20e34c r5:cf0903e0 r4:cf090000
[   11.360000] [<bf1fb30c>] (wilc_mac_open [wilc_spi]) from [<c0304e98>] (__dev_open+0xf4/0x110)
[   11.360000]  r10:bedffa60 r9:00000000 r8:cec0a90c r7:00001002 r6:00001003 r5:bf207900
[   11.360000]  r4:cf090000
[   11.360000] [<c0304da4>] (__dev_open) from [<c03050e0>] (__dev_change_flags+0x9c/0x13c)
[   11.360000]  r5:00000001 r4:cf090000
[   11.360000] [<c0305044>] (__dev_change_flags) from [<c03051a0>] (dev_change_flags+0x20/0x50)
[   11.360000]  r9:00000000 r8:cec0a90c r7:00001002 r6:cf090150 r5:00000000 r4:cf090000
[   11.360000] [<c0305180>] (dev_change_flags) from [<c035dd58>] (devinet_ioctl+0x2f0/0x66c)
[   11.360000]  r9:00000000 r8:cec0a90c r7:cec0a900 r6:00000000 r5:cf090000 r4:00000000
[   11.360000] [<c035da68>] (devinet_ioctl) from [<c035f9c0>] (inet_ioctl+0xa0/0xf4)
[   11.360000]  r10:00000036 r9:cf3fa000 r8:cf08bcc0 r7:bedffa60 r6:bedffa60 r5:00008914
[   11.360000]  r4:bedffa60
[   11.360000] [<c035f920>] (inet_ioctl) from [<c02eb2cc>] (sock_ioctl+0x9c/0x29c)
[   11.360000]  r5:00008914 r4:bedffa60
[   11.360000] [<c02eb230>] (sock_ioctl) from [<c0197f24>] (vfs_ioctl+0x28/0x3c)
[   11.360000]  r7:bedffa60 r6:cf08bcc0 r5:cf517660 r4:bedffa60
[   11.360000] [<c0197efc>] (vfs_ioctl) from [<c01984cc>] (do_vfs_ioctl+0xa4/0x830)
[   11.360000] [<c0198428>] (do_vfs_ioctl) from [<c0198c98>] (SyS_ioctl+0x40/0x5c)
[   11.360000]  r10:00000036 r9:cf3fa000 r8:cf08bcc0 r7:bedffa60 r6:00008914 r5:00000008
[   11.360000]  r4:cf08bcc0
[   11.360000] [<c0198c58>] (SyS_ioctl) from [<c0106c80>] (ret_fast_syscall+0x0/0x48)
[   11.360000]  r9:cf3fa000 r8:c0106e64 r7:00000036 r6:00000001 r5:005967b8 r4:00000000
[   11.360000] ---[ end trace 466674c1e7cf2e1a ]---
[   11.360000] WILC_SPI spi32765.0: spi transfer timeout
[   11.370000] WILC_SPI spi32765.0: SPI transaction failed
[   11.370000] WILC_SPI spi32765.0: Failed cmd write, bus error...
[   11.380000] WILC_SPI spi32765.0: Failed internal read cmd...
[   11.400000] WILC_SPI spi32765.0: Reset and retry 10 24