linux-next 20170110 didn't exhibit this. Am seeing at boot a lockdep whine, followed by 3 BUGs. ata_scsi_rbuf_fill() is in the traceback for all of them. 'git log' hints that it's one of 6 commits against drivers/ata/libata-scsi.c by Christoph, but none of them spring out as being the guilty party. This ring any bells, or should I start cherrypicking reverts and bisecting? (-dirty due to a local patch to net/ipv6/addrconf.c for a VPN issue) Lockdep: [ 3.359133] ================================= [ 3.359162] [ INFO: inconsistent lock state ] [ 3.359192] 4.10.0-rc4-next-20170117-dirty #375 Not tainted [ 3.359229] --------------------------------- [ 3.359258] inconsistent {IN-HARDIRQ-W} -> {HARDIRQ-ON-W} usage. [ 3.359299] kworker/u8:0/5 [HC0[0]:SC0[0]:HE1:SE1] takes: [ 3.359334] (&(&host->lock)->rlock){?.....}, at: [<ffffffffa99f4e4f>] ata_scsi_queuecmd+0x4f/0x420 [ 3.359398] {IN-HARDIRQ-W} state was registered at: [ 3.359431] [ 3.359434] [<ffffffffa915cc66>] __lock_acquire+0x636/0x18b0 [ 3.359484] [ 3.359486] [<ffffffffa915e4d9>] lock_acquire+0x119/0x2d0 [ 3.359533] [ 3.359535] [<ffffffffaa1baf01>] _raw_spin_lock+0x41/0x80 [ 3.359582] [ 3.359584] [<ffffffffa9a0be14>] ahci_single_level_irq_intr+0x44/0x90 [ 3.359638] [ 3.359640] [<ffffffffa91710f7>] __handle_irq_event_percpu+0x127/0x690 [ 3.359694] [ 3.359696] [<ffffffffa9171694>] handle_irq_event_percpu+0x34/0xb0 [ 3.359747] [ 3.359749] [<ffffffffa917175b>] handle_irq_event+0x4b/0xc0 [ 3.359797] [ 3.359799] [<ffffffffa9177725>] handle_edge_irq+0xb5/0x3d0 [ 3.359847] [ 3.359849] [<ffffffffa90396d6>] handle_irq+0xa6/0x2c0 [ 3.359895] [ 3.359897] [<ffffffffaa1be4f3>] do_IRQ+0x83/0x1b0 [ 3.359940] [ 3.359942] [<ffffffffaa1bc8d0>] ret_from_intr+0x0/0x19 [ 3.359989] [ 3.359992] [<ffffffffa9bb87c4>] cpuidle_enter_state+0xe4/0x660 [ 3.360043] [ 3.360045] [<ffffffffa9bb8d97>] cpuidle_enter+0x17/0x20 [ 3.360092] [ 3.360095] [<ffffffffa9147757>] do_idle+0x2f7/0x3d0 [ 3.360139] [ 3.360142] [<ffffffffa9147f5c>] cpu_startup_entry+0x7c/0x90 [ 3.360190] [ 3.360193] [<ffffffffaa1a959c>] rest_init+0x15c/0x170 [ 3.360239] [ 3.360242] [<ffffffffab63a734>] start_kernel+0x747/0x788 [ 3.360288] [ 3.360291] [<ffffffffab6383b8>] x86_64_start_reservations+0x4f/0x70 [ 3.360344] [ 3.360346] [<ffffffffab63871d>] x86_64_start_kernel+0x344/0x38b [ 3.360397] [ 3.360400] [<ffffffffa90001c4>] verify_cpu+0x0/0xf1 [ 3.360445] irq event stamp: 160102 [ 3.360470] hardirqs last enabled at (160101): [<ffffffffaa1bb47e>] _raw_spin_unlock_irq+0x2e/0x80 [ 3.360529] hardirqs last disabled at (160102): [<ffffffffaa1bb15e>] _raw_spin_lock_irqsave+0x1e/0x90 [ 3.360589] softirqs last enabled at (159762): [<ffffffffaa1c1ded>] __do_softirq+0x55d/0xa39 [ 3.360644] softirqs last disabled at (159741): [<ffffffffa90c2a81>] irq_exit+0x111/0x170 [ 3.360695] other info that might help us debug this: [ 3.360737] Possible unsafe locking scenario: [ 3.360775] CPU0 [ 3.360793] ---- [ 3.360810] lock(&(&host->lock)->rlock); [ 3.360839] <Interrupt> [ 3.360857] lock(&(&host->lock)->rlock); [ 3.360887] *** DEADLOCK *** [ 3.360926] 4 locks held by kworker/u8:0/5: [ 3.360954] #0: ("events_unbound"){.+.+.+}, at: [<ffffffffa90ef887>] process_one_work+0x347/0xe10 [ 3.361015] #1: ((&entry->work)){+.+.+.}, at: [<ffffffffa90ef887>] process_one_work+0x347/0xe10 [ 3.361075] #2: (&shost->scan_mutex){+.+.+.}, at: [<ffffffffa99c258c>] __scsi_add_device+0xac/0x150 [ 3.361137] #3: (&(&host->lock)->rlock){?.....}, at: [<ffffffffa99f4e4f>] ata_scsi_queuecmd+0x4f/0x420 [ 3.362428] usbcore: registered new interface driver uvcvideo [ 3.362429] USB Video Class driver (1.1.1) [ 3.367023] stack backtrace: [ 3.370918] CPU: 1 PID: 5 Comm: kworker/u8:0 Not tainted 4.10.0-rc4-next-20170117-dirty #375 [ 3.372913] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015 [ 3.374918] Workqueue: events_unbound async_run_entry_fn [ 3.376925] Call Trace: [ 3.378912] dump_stack+0x7b/0xd1 [ 3.380888] print_usage_bug+0x27b/0x330 [ 3.382850] mark_lock+0x6ea/0x8a0 [ 3.384787] ? print_shortest_lock_dependencies+0x380/0x380 [ 3.386726] mark_held_locks+0x93/0x160 [ 3.388651] ? add_lock_to_list.isra.17.constprop.33+0xa7/0x160 [ 3.390591] ? cache_alloc_refill+0x9dd/0x1360 [ 3.392533] trace_hardirqs_on_caller+0x103/0x2c0 [ 3.394464] trace_hardirqs_on+0xd/0x10 [ 3.396390] cache_alloc_refill+0x9dd/0x1360 [ 3.398301] ? ___might_sleep+0x1e2/0x300 [ 3.400203] ? __might_sleep+0x66/0x1f0 [ 3.402091] kmem_cache_alloc_trace+0xf3/0x4f0 [ 3.403976] ? ata_scsiop_inq_00+0x160/0x160 [ 3.405854] ata_scsi_rbuf_fill+0x39/0x110 [ 3.407696] ata_scsi_simulate+0x2e8/0x4b0 [ 3.409533] ata_scsi_queuecmd+0x303/0x420 [ 3.411350] scsi_dispatch_cmd+0x188/0x690 [ 3.413154] scsi_request_fn+0x709/0xd00 [ 3.414958] __blk_run_queue+0x7e/0xb0 [ 3.416733] blk_execute_rq_nowait+0x1c5/0x210 [ 3.418515] ? blk_execute_rq_nowait+0x210/0x210 [ 3.420304] blk_execute_rq+0x14b/0x210 [ 3.422088] ? blk_rq_append_bio+0x9d/0x100 [ 3.423864] ? blk_rq_map_kern+0x11b/0x200 [ 3.425584] ? blk_get_request+0x149/0x290 [ 3.427285] __scsi_execute+0x148/0x210 [ 3.429035] scsi_execute_req_flags+0x98/0x110 [ 3.430786] scsi_probe_and_add_lun+0x29e/0x1210 [ 3.432519] ? _raw_spin_unlock_irqrestore+0x87/0x90 [ 3.434250] ? __pm_runtime_resume+0x52/0x90 [ 3.435972] __scsi_add_device+0x121/0x150 [ 3.437701] ata_scsi_scan_host+0x127/0x240 [ 3.439424] async_port_probe+0x4a/0x90 [ 3.441127] async_run_entry_fn+0x66/0x2b0 [ 3.442828] process_one_work+0x3dc/0xe10 [ 3.444522] ? process_one_work+0x347/0xe10 [ 3.446203] worker_thread+0x352/0xb40 [ 3.447882] kthread+0x176/0x250 [ 3.449543] ? process_one_work+0xe10/0xe10 [ 3.451215] ? kthread_create_on_node+0x60/0x60 [ 3.452866] ret_from_fork+0x2e/0x40 [ 3.454614] scsi 0:0:0:0: Direct-Access ATA ST500LX003-1AC15 DEM4 PQ: 0 ANSI: 5 The 3 BUGs have essentially the same traceback: [ 4.260406] BUG: sleeping function called from invalid context at mm/slab.h:408 [ 4.264460] in_atomic(): 1, irqs_disabled(): 1, pid: 362, name: ata_id [ 4.268485] INFO: lockdep is turned off. [ 4.272516] irq event stamp: 0 [ 4.276490] hardirqs last enabled at (0): [< (null)>] (null) [ 4.280535] hardirqs last disabled at (0): [<ffffffffa90b23db>] copy_process.part.33+0xb0b/0x3b50 [ 4.284604] softirqs last enabled at (0): [<ffffffffa90b23db>] copy_process.part.33+0xb0b/0x3b50 [ 4.288538] softirqs last disabled at (0): [< (null)>] (null) [ 4.292428] CPU: 2 PID: 362 Comm: ata_id Not tainted 4.10.0-rc4-next-20170117-dirty #375 [ 4.296395] Hardware name: Dell Inc. Latitude E6530/07Y85M, BIOS A17 08/19/2015 [ 4.300432] Call Trace: [ 4.304460] dump_stack+0x7b/0xd1 [ 4.308451] ___might_sleep+0x194/0x300 [ 4.312457] __might_sleep+0x66/0x1f0 [ 4.316420] kmem_cache_alloc_trace+0x2fc/0x4f0 [ 4.320436] ? ata_scsiop_inq_00+0x160/0x160 [ 4.323049] ata_scsi_rbuf_fill+0x39/0x110 [ 4.325212] ata_scsi_simulate+0x2e8/0x4b0 [ 4.327388] ata_scsi_queuecmd+0x303/0x420 [ 4.329549] scsi_dispatch_cmd+0x188/0x690 [ 4.331733] scsi_request_fn+0x709/0xd00 [ 4.333853] __blk_run_queue+0x7e/0xb0 [ 4.335945] __elv_add_request+0x1f2/0x680 [ 4.338105] blk_execute_rq_nowait+0x1bd/0x210 [ 4.340235] ? blk_execute_rq_nowait+0x210/0x210 [ 4.342334] blk_execute_rq+0x14b/0x210 [ 4.344459] ? blk_rq_map_user+0x92/0xe0 [ 4.346597] sg_io+0x357/0x510 [ 4.348734] ? __check_object_size+0x19d/0x4f8 [ 4.350852] scsi_cmd_ioctl+0x38d/0x540 [ 4.352944] scsi_cmd_blk_ioctl+0x50/0x80 [ 4.355027] sd_ioctl+0x8f/0xf0 [ 4.357103] blkdev_ioctl+0x5ed/0x1090 [ 4.359183] ? trace_hardirqs_on_caller+0x16/0x2c0 [ 4.361277] block_ioctl+0x57/0xa0 [ 4.363295] do_vfs_ioctl+0xc0/0xb00 [ 4.365325] SyS_ioctl+0x79/0x90 [ 4.367319] do_syscall_64+0x8c/0x290 [ 4.369243] entry_SYSCALL64_slow_path+0x25/0x25 [ 4.371159] RIP: 0033:0x7ff3910156c7 [ 4.373051] RSP: 002b:00007ffcc3a22448 EFLAGS: 00000246 ORIG_RAX: 0000000000000010 [ 4.374956] RAX: ffffffffffffffda RBX: 0000000000000001 RCX: 00007ff3910156c7 [ 4.376846] RDX: 00007ffcc3a224a0 RSI: 0000000000002285 RDI: 0000000000000003 [ 4.378714] RBP: 00007ffcc3a22b90 R08: 0000000000000000 R09: 0000000000000000 [ 4.380543] R10: 00007ff391b3e080 R11: 0000000000000246 R12: 00000000ffffffff [ 4.382391] R13: 00007ffcc3a22f1a R14: 00007ffcc3a22700 R15: 0000000000000003 [ 4.386253] ata_id (362) used greatest stack depth: 12136 bytes left
Attachment:
pgpSbH41Na2DH.pgp
Description: PGP signature