search

raspberrypi / linux

Kernel source tree for Raspberry Pi-provided kernel builds. Issues unrelated to the linux kernel should be posted on the community forum at https://forums.raspberrypi.com/
Other
11.06k stars 4.97k forks source link

WARNING: inconsistent lock state #2654

Open ghost opened 6 years ago

ghost commented 6 years ago

When enable CONFIG_PROVE_LOCKING we have 

[    0.000000] Linux version 4.14.61-v7+ (tanure@Debian9) (gcc version 4.9.4 (Linaro GCC 4.9-2017.01)) #2 SMP Wed Aug 22 17:25:31 BST 2018
[    0.000000] CPU: ARMv7 Processor [410fd034] revision 4 (ARMv7), cr=10c5383d
[    0.000000] CPU: div instructions available: patching division code
[    0.000000] CPU: PIPT / VIPT nonaliasing data cache, VIPT aliasing instruction cache
[    0.000000] OF: fdt: Machine model: Raspberry Pi 3 Model B Rev 1.2
[    0.000000] Memory policy: Data cache writealloc
[    0.000000] cma: Reserved 8 MiB at 0x3ac00000
[    0.000000] On node 0 totalpages: 242688
[    0.000000] free_area_init_node: node 0, pgdat 80d95940, node_mem_map ba39f000
[    0.000000]   Normal zone: 2133 pages used for memmap
[    0.000000]   Normal zone: 0 pages reserved
[    0.000000]   Normal zone: 242688 pages, LIFO batch:31
[    0.000000] percpu: Embedded 17 pages/cpu @ba341000 s40064 r8192 d21376 u69632
[    0.000000] pcpu-alloc: s40064 r8192 d21376 u69632 alloc=17*4096
[    0.000000] pcpu-alloc: [0] 0 [0] 1 [0] 2 [0] 3 
[    0.000000] Built 1 zonelists, mobility grouping on.  Total pages: 240555
[    0.000000] Kernel command line: 8250.nr_uarts=1 bcm2708_fb.fbwidth=656 bcm2708_fb.fbheight=416 bcm2708_fb.fbswap=1 vc_mem.mem_base=0x3ec00000 vc_mem.mem_size=0x40000000  loglevel=8 dwct
[    0.000000] PID hash table entries: 4096 (order: 2, 16384 bytes)
[    0.000000] Dentry cache hash table entries: 131072 (order: 7, 524288 bytes)
[    0.000000] Inode-cache hash table entries: 65536 (order: 6, 262144 bytes)
[    0.000000] Memory: 931740K/970752K available (8192K kernel code, 645K rwdata, 2256K rodata, 1024K init, 8065K bss, 30820K reserved, 8192K 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 : 0xbb800000 - 0xff800000   (1088 MB)
[    0.000000]     lowmem  : 0x80000000 - 0xbb400000   ( 948 MB)
[    0.000000]     modules : 0x7f000000 - 0x80000000   (  16 MB)
[    0.000000]       .text : 0x80008000 - 0x80900000   (9184 kB)
[    0.000000]       .init : 0x80c00000 - 0x80d00000   (1024 kB)
[    0.000000]       .data : 0x80d00000 - 0x80da1434   ( 646 kB)
[    0.000000]        .bss : 0x80da9120 - 0x8158959c   (8066 kB)
[    0.000000] SLUB: HWalign=64, Order=0-3, MinObjects=0, CPUs=4, Nodes=1
[    0.000000] ftrace: allocating 25414 entries in 75 pages
[    0.000000] Running RCU self tests
[    0.000000] Hierarchical RCU implementation.
[    0.000000]  RCU lockdep checking is enabled.
[    0.000000] NR_IRQS: 16, nr_irqs: 16, preallocated irqs: 16
[    0.000000] arch_timer: cp15 timer(s) running at 19.20MHz (phys).
[    0.000000] clocksource: arch_sys_counter: mask: 0xffffffffffffff max_cycles: 0x46d987e47, max_idle_ns: 440795202767 ns
[    0.000009] sched_clock: 56 bits at 19MHz, resolution 52ns, wraps every 4398046511078ns
[    0.000035] Switching to timer-based delay loop, resolution 52ns
[    0.000720] Console: colour dummy device 80x30
[    0.005164] console [tty1] enabled
[    0.005244] Lock dependency validator: Copyright (c) 2006 Red Hat, Inc., Ingo Molnar
[    0.005382] ... MAX_LOCKDEP_SUBCLASSES:  8
[    0.005464] ... MAX_LOCK_DEPTH:          48
[    0.005547] ... MAX_LOCKDEP_KEYS:        8191
[    0.005632] ... CLASSHASH_SIZE:          4096
[    0.005717] ... MAX_LOCKDEP_ENTRIES:     32768
[    0.005804] ... MAX_LOCKDEP_CHAINS:      65536
[    0.005890] ... CHAINHASH_SIZE:          32768
[    0.005977]  memory used by lock dependency info: 4655 kB
[    0.006077]  per task-struct memory footprint: 1536 bytes
[    0.006244] Calibrating delay loop (skipped), value calculated using timer frequency.. 38.40 BogoMIPS (lpj=192000)
[    0.006439] pid_max: default: 32768 minimum: 301
[    0.007153] Mount-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.007284] Mountpoint-cache hash table entries: 2048 (order: 1, 8192 bytes)
[    0.012510] Disabling memory control group subsystem
[    0.012964] CPU: Testing write buffer coherency: ok
[    0.015112] CPU0: thread -1, cpu 0, socket 0, mpidr 80000000
[    0.017024] Setting up static identity map for 0x100000 - 0x10003c
[    0.017776] Hierarchical SRCU implementation.
[    0.020483] smp: Bringing up secondary CPUs ...
[    0.023522] CPU1: thread -1, cpu 1, socket 0, mpidr 80000001
[    0.026580] CPU2: thread -1, cpu 2, socket 0, mpidr 80000002
[    0.029040] CPU3: thread -1, cpu 3, socket 0, mpidr 80000003
[    0.029428] smp: Brought up 1 node, 4 CPUs
[    0.029852] SMP: Total of 4 processors activated (153.60 BogoMIPS).
[    0.029983] CPU: All CPU(s) started in HYP mode.
[    0.030085] CPU: Virtualization extensions available.
[    0.034624] devtmpfs: initialized
[    0.073970] random: get_random_u32 called from bucket_table_alloc+0xe8/0x260 with crng_init=0
[    0.075395] VFP support v0.3: implementor 41 architecture 3 part 40 variant 3 rev 4
[    0.078601] clocksource: jiffies: mask: 0xffffffff max_cycles: 0xffffffff, max_idle_ns: 19112604462750000 ns
[    0.078856] futex hash table entries: 1024 (order: 4, 65536 bytes)
[    0.080716] pinctrl core: initialized pinctrl subsystem
[    0.086731] NET: Registered protocol family 16
[    0.093242] DMA: preallocated 1024 KiB pool for atomic coherent allocations
[    0.109691] hw-breakpoint: found 5 (+1 reserved) breakpoint and 4 watchpoint registers.
[    0.109865] hw-breakpoint: maximum watchpoint size is 8 bytes.
[    0.110286] Serial: AMBA PL011 UART driver
[    0.115924] bcm2835-mbox 3f00b880.mailbox: mailbox enabled
[    0.117514] uart-pl011 3f201000.serial: could not find pctldev for node /soc/gpio@7e200000/uart0_pins, deferring probe
[    0.230787] bcm2835-dma 3f007000.dma: DMA legacy API manager at bb813000, dmachans=0x1
[    0.235954] SCSI subsystem initialized
[    0.236944] usbcore: registered new interface driver usbfs
[    0.237293] usbcore: registered new interface driver hub
[    0.237715] usbcore: registered new device driver usb
[    0.241588] raspberrypi-firmware soc:firmware: Attached to firmware from 2018-08-16 17:30
[    0.246981] clocksource: Switched to clocksource arch_sys_counter
[    0.482446] VFS: Disk quotas dquot_6.6.0
[    0.482694] VFS: Dquot-cache hash table entries: 1024 (order 0, 4096 bytes)
[    0.483360] FS-Cache: Loaded
[    0.484770] CacheFiles: Loaded
[    0.516743] NET: Registered protocol family 2
[    0.519530] TCP established hash table entries: 8192 (order: 3, 32768 bytes)
[    0.519900] TCP bind hash table entries: 8192 (order: 6, 294912 bytes)
[    0.525125] TCP: Hash tables configured (established 8192 bind 8192)
[    0.525808] UDP hash table entries: 512 (order: 3, 40960 bytes)
[    0.526647] UDP-Lite hash table entries: 512 (order: 3, 40960 bytes)
[    0.529328] NET: Registered protocol family 1
[    0.531284] RPC: Registered named UNIX socket transport module.
[    0.531448] RPC: Registered udp transport module.
[    0.531556] RPC: Registered tcp transport module.
[    0.531663] RPC: Registered tcp NFSv4.1 backchannel transport module.
[    0.537815] hw perfevents: enabled with armv7_cortex_a7 PMU driver, 7 counters available
[    0.550105] workingset: timestamp_bits=14 max_order=18 bucket_order=4
[    0.578860] FS-Cache: Netfs 'nfs' registered for caching
[    0.581395] NFS: Registering the id_resolver key type
[    0.582056] Key type id_resolver registered
[    0.582189] Key type id_legacy registered
[    0.582309] nfs4filelayout_init: NFSv4 File Layout Driver Registering...
[    0.590615] Block layer SCSI generic (bsg) driver version 0.4 loaded (major 251)
[    0.591321] io scheduler noop registered
[    0.591420] io scheduler deadline registered (default)
[    0.592439] io scheduler cfq registered
[    0.592535] io scheduler mq-deadline registered
[    0.592639] io scheduler kyber registered
[    0.601995] BCM2708FB: allocated DMA memory fad10000
[    0.602313] BCM2708FB: allocated DMA channel 0 @ bb813000
[    0.613862] Console: switching to colour frame buffer device 82x26
[    0.624073] Serial: 8250/16550 driver, 1 ports, IRQ sharing enabled
[    0.631536] bcm2835-rng 3f104000.rng: hwrng registered
[    0.634294] vc-mem: phys_addr:0x00000000 mem_base=0x3ec00000 mem_size:0x40000000(1024 MiB)
[    0.640806] vc-sm: Videocore shared memory driver
[    0.644363] gpiomem-bcm2835 3f200000.gpiomem: Initialised: Registers at 0x3f200000
[    0.681420] brd: module loaded
[    0.719061] loop: module loaded
[    0.721505] Loading iSCSI transport class v2.0-870.
[    0.726351] libphy: Fixed MDIO Bus: probed
[    0.729069] usbcore: registered new interface driver lan78xx
[    0.731587] usbcore: registered new interface driver smsc95xx
[    0.733916] dwc_otg: version 3.00a 10-AUG-2012 (platform bus)
[    0.765028] dwc_otg 3f980000.usb: base=0xf0980000
[    0.968143] Core Release: 2.80a
[    0.970488] Setting default values for core params
[    0.972929] Finished setting default values for core params
[    1.176008] Using Buffer DMA mode
[    1.178499] Periodic Transfer Interrupt Enhancement - disabled
[    1.181015] Multiprocessor Interrupt Enhancement - disabled
[    1.183510] OTG VER PARAM: 0, OTG VER FLAG: 0
[    1.185947] Dedicated Tx FIFOs mode
[    1.189221] WARN::dwc_otg_hcd_init:1046: FIQ DMA bounce buffers: virt = 0xbad04000 dma = 0xfad04000 len=9024
[    1.193989] FIQ FSM acceleration enabled for :
[    1.193989] Non-periodic Split Transactions
[    1.193989] Periodic Split Transactions
[    1.193989] High-Speed Isochronous Endpoints
[    1.193989] Interrupt/Control Split Transaction hack enabled
[    1.205352] dwc_otg: Microframe scheduler enabled
[    1.207900] WARN::hcd_init_fiq:459: FIQ on core 1 at 0x8066bd6c
[    1.210296] WARN::hcd_init_fiq:460: FIQ ASM at 0x8066c0d0 length 36
[    1.212737] WARN::hcd_init_fiq:486: MPHI regs_base at 0xf0006000
[    1.215238] 
[    1.217432] ================================
[    1.219684] WARNING: inconsistent lock state
[    1.221926] 4.14.61-v7+ #2 Not tainted
[    1.224124] --------------------------------
[    1.226301] inconsistent {HARDIRQ-ON-W} -> {IN-HARDIRQ-W} usage.
[    1.228533] swapper/1/0 [HC1[1]:SC0[0]:HE0:SE1] takes:
[    1.230739]  (irq_domain_mutex){?.+.}, at: [<80195578>] irq_find_matching_fwspec+0x38/0x124
[    1.235295] {HARDIRQ-ON-W} state was registered at:
[    1.237599]   lock_acquire+0xd0/0x248
[    1.239795]   __mutex_lock+0x60/0x9c0
[    1.241936]   mutex_lock_nested+0x2c/0x34
[    1.244081]   irq_find_matching_fwspec+0x38/0x124
[    1.246263]   of_irq_get+0x58/0x78
[    1.248423]   of_irq_to_resource+0x28/0xcc
[    1.250558]   of_irq_to_resource_table+0x4c/0x5c
[    1.252644]   of_device_alloc+0x100/0x184
[    1.254670]   of_platform_device_create_pdata+0x58/0xac
[    1.256745]   of_platform_bus_create+0x104/0x35c
[    1.258794]   of_platform_bus_create+0x160/0x35c
[    1.260744]   of_platform_populate+0x7c/0xdc
[    1.262665]   of_platform_default_populate_init+0x80/0x90
[    1.264614]   do_one_initcall+0x50/0x180
[    1.266541]   kernel_init_freeable+0x264/0x300
[    1.268474]   kernel_init+0x18/0x128
[    1.270324]   ret_from_fork+0x14/0x28
[    1.272110] irq event stamp: 1798
[    1.273808] hardirqs last  enabled at (1795): [<80108d08>] arch_cpu_idle+0x30/0x4c
[    1.277219] hardirqs last disabled at (1796): [<80860aec>] __irq_svc+0x4c/0x7c
[    1.279126] softirqs last  enabled at (1798): [<8012599c>] _local_bh_enable+0x34/0x68
[    1.282903] softirqs last disabled at (1797): [<80125e00>] irq_enter+0x68/0x94
[    1.285018] 
[    1.285018] other info that might help us debug this:
[    1.289153]  Possible unsafe locking scenario:
[    1.289153] 
[    1.293389]        CPU0
[    1.295431]        ----
[    1.297422]   lock(irq_domain_mutex);
[    1.299503]   <Interrupt>
[    1.301544]     lock(irq_domain_mutex);
[    1.303625] 
[    1.303625]  *** DEADLOCK ***
[    1.303625] 
[    1.309438] no locks held by swapper/1/0.
[    1.311429] 
[    1.311429] stack backtrace:
[    1.315197] CPU: 1 PID: 0 Comm: swapper/1 Not tainted 4.14.61-v7+ #2
[    1.317113] Hardware name: BCM2835
[    1.318922] [<80110a40>] (unwind_backtrace) from [<8010cbb4>] (show_stack+0x20/0x24)
[    1.322667] [<8010cbb4>] (show_stack) from [<80842fc8>] (dump_stack+0xd4/0x118)
[    1.324654] [<80842fc8>] (dump_stack) from [<80180c28>] (print_usage_bug+0x23c/0x2e8)
[    1.328387] [<80180c28>] (print_usage_bug) from [<80180ee0>] (mark_lock+0x20c/0x770)
[    1.332446] [<80180ee0>] (mark_lock) from [<80182654>] (__lock_acquire+0xb94/0x1c04)
[    1.337044] [<80182654>] (__lock_acquire) from [<80184020>] (lock_acquire+0xd0/0x248)
[    1.342118] [<80184020>] (lock_acquire) from [<8085b37c>] (__mutex_lock+0x60/0x9c0)
[    1.347604] [<8085b37c>] (__mutex_lock) from [<8085bd08>] (mutex_lock_nested+0x2c/0x34)
[    1.353608] [<8085bd08>] (mutex_lock_nested) from [<80195578>] (irq_find_matching_fwspec+0x38/0x124)
[    1.360072] [<80195578>] (irq_find_matching_fwspec) from [<806dd428>] (of_irq_get+0x58/0x78)
[    1.366923] [<806dd428>] (of_irq_get) from [<805c1960>] (platform_get_irq+0x2c/0x104)
[    1.373910] [<805c1960>] (platform_get_irq) from [<80662bf8>] (hcd_init_fiq+0x20c/0x290)
[    1.380924] [<80662bf8>] (hcd_init_fiq) from [<801bff88>] (flush_smp_call_function_queue+0xac/0x1b0)
[    1.388124] [<801bff88>] (flush_smp_call_function_queue) from [<801c0d64>] (generic_smp_call_function_single_interrupt+0x1c/0x20)
[    1.395393] [<801c0d64>] (generic_smp_call_function_single_interrupt) from [<8010ecf8>] (handle_IPI+0x1ac/0x3fc)
[    1.402620] [<8010ecf8>] (handle_IPI) from [<80101528>] (bcm2836_arm_irqchip_handle_irq+0x80/0xb0)
[    1.409818] [<80101528>] (bcm2836_arm_irqchip_handle_irq) from [<80860afc>] (__irq_svc+0x5c/0x7c)
[    1.417006] Exception stack(0xb9d33f38 to 0xb9d33f80)
[    1.420577] 3f20:                                                       00000001 00000001
[    1.427427] 3f40: 00000000 b9d38000 b9d32000 80d075cc 80d07568 80d98db5 00000001 410fd034
[    1.434155] 3f60: 00000000 b9d33f94 b9d33f58 b9d33f88 80181644 80108d0c 20000013 ffffffff
[    1.440870] [<80860afc>] (__irq_svc) from [<80108d0c>] (arch_cpu_idle+0x34/0x4c)
[    1.447551] [<80108d0c>] (arch_cpu_idle) from [<8085ff0c>] (default_idle_call+0x34/0x48)
[    1.454229] [<8085ff0c>] (default_idle_call) from [<8016ff0c>] (do_idle+0xd8/0x150)
[    1.460890] [<8016ff0c>] (do_idle) from [<80170334>] (cpu_startup_entry+0x28/0x2c)
[    1.467542] [<80170334>] (cpu_startup_entry) from [<8010e900>] (secondary_start_kernel+0x130/0x13c)
[    1.474224] [<8010e900>] (secondary_start_kernel) from [<00101bac>] (0x101bac)
[    1.477738] dwc_otg 3f980000.usb: DWC OTG Controller
[    1.481169] dwc_otg 3f980000.usb: new USB bus registered, assigned bus number 1
[    1.484588] dwc_otg 3f980000.usb: irq 62, io mem 0x00000000
[    1.487975] Init: Port Power? op_state=1
[    1.491214] Init: Power Port (0)
[    1.494787] usb usb1: New USB device found, idVendor=1d6b, idProduct=0002
[    1.498125] usb usb1: New USB device strings: Mfr=3, Product=2, SerialNumber=1
[    1.501373] usb usb1: Product: DWC OTG Controller
[    1.504506] usb usb1: Manufacturer: Linux 4.14.61-v7+ dwc_otg_hcd
[    1.507650] usb usb1: SerialNumber: 3f980000.usb
[    1.511706] hub 1-0:1.0: USB hub found
[    1.514658] hub 1-0:1.0: 1 port detected
pelwell commented 6 years ago

This is a close relative of #2612, both of which are caused by the fact that the DWC_OTG FIQ support relies on the SMP call mechanism to run a function on a specific core, and that function runs with interrupts disabled.

Any thoughts, @P33M?

JamesH65 commented 5 years ago

@p33m

pelwell commented 5 years ago

Probably fixed by https://github.com/raspberrypi/linux/commit/d903e18191d372cf917b0db788b5cd43bcd16025.