From mboxrd@z Thu Jan 1 00:00:00 1970 From: Valdis.Kletnieks@vt.edu Subject: mmotm 2011-06-22 - inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage. Date: Wed, 22 Jun 2011 21:59:51 -0400 Message-ID: <6189.1308794391@turing-police.cc.vt.edu> References: <201106222042.p5MKgiEe025352@imap1.linux-foundation.org> Mime-Version: 1.0 Content-Type: multipart/signed; boundary="==_Exmh_1308794391_4530P"; micalg=pgp-sha1; protocol="application/pgp-signature" Content-Transfer-Encoding: 7bit Return-path: In-Reply-To: Your message of "Wed, 22 Jun 2011 13:05:19 PDT." <201106222042.p5MKgiEe025352@imap1.linux-foundation.org> Sender: linux-kernel-owner@vger.kernel.org To: Andrew Morton , Thomas Gleixner , Jeff Garzik , Peter Zijlstra , IngIngo Molnar Cc: linux-kernel@vger.kernel.org, linux-ide@vger.kernel.org List-Id: linux-ide@vger.kernel.org --==_Exmh_1308794391_4530P Content-Type: text/plain; charset=us-ascii On Wed, 22 Jun 2011 13:05:19 PDT, akpm@linux-foundation.org said: > The mm-of-the-moment snapshot 2011-06-22-13-05 has been uploaded to Nothing obvious to cause it, and I didn't see it in -rc3-mmotm0615, so I'll toss this at Andrew and everybody mentioned in MAINTAINERS for SATA, IRQs, and Lockdep and see if anybody has a brilliant idea. Quite probably relevant - kernel was booted with 'threadirqs', but that's been in there since 39-rc7 and I haven't seen this before. Threw an amazing traceback on boot while trying to fsck the / filesystem on a LUKS-encrypted LVM partition: [ 3.828296] dracut: luksOpen /dev/sda2 luks-715ceabf-6f58-4251-9373-ed29e8629a7c [ 18.127342] dracut: Scanning devices dm-0 for LVM volume groups [ 18.164842] dracut: Reading all physical volumes. This may take a while... [ 18.164995] dracut: Found volume group "vg_blackice" using metadata type lvm2 [ 18.557728] blkid used greatest stack depth: 3904 bytes left [ 20.095210] dracut: 12 logical volume(s) in volume group "vg_blackice" now active [ 20.174640] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: (null) [ 20.233169] dracut: Checking filesystems [ 20.233210] dracut: fsck -T -t noopts=_netdev -A -a [ 20.253331] [ 20.253500] ================================= [ 20.253803] [ INFO: inconsistent lock state ] [ 20.254107] 3.0.0-rc4-mmotm0622 #1 [ 20.254275] --------------------------------- [ 20.254275] inconsistent {SOFTIRQ-ON-W} -> {IN-SOFTIRQ-W} usage. [ 20.254275] irq/45-ahci/47 [HC0[0]:SC1[1]:HE0:SE0] takes: [ 20.254275] (&(&mapping->tree_lock)->rlock){+.?...}, at: [] test_clear_page_writeback+0x39/0xd3 [ 20.254275] {SOFTIRQ-ON-W} state was registered at: [ 20.254275] [] mark_irqflags+0xf2/0x13e [ 20.254275] [] __lock_acquire+0x22b/0x3e2 [ 20.254275] [] lock_acquire+0x103/0x153 [ 20.254275] [] _raw_spin_lock+0x36/0x45 [ 20.254275] [] end_writeback+0x33/0x103 [ 20.254275] [] bdev_evict_inode+0x3e/0xbe [ 20.254275] [] evict+0xb0/0x173 [ 20.254275] [] iput_final+0x171/0x17a [ 20.254275] [] iput+0x4e/0x53 [ 20.254275] [] __blkdev_put+0x1c0/0x1eb [ 20.254275] [] blkdev_put+0x1e6/0x1f5 [ 20.254275] [] register_disk+0xea/0x13c [ 20.254275] [] add_disk+0x12f/0x1a4 [ 20.254275] [] sd_probe_async+0x115/0x1b5 [ 20.254275] [] async_run_entry_fn+0x99/0x12a [ 20.254275] [] process_one_work+0x25d/0x467 [ 20.254275] [] worker_thread+0x152/0x206 [ 20.254275] [] kthread+0x7f/0x87 [ 20.254275] [] kernel_thread_helper+0x4/0x10 [ 20.254275] irq event stamp: 115999 [ 20.254275] hardirqs last enabled at (115998): [] end_buffer_async_write.part.14+0x117/0x154 [ 20.254275] hardirqs last disabled at (115999): [] _raw_spin_lock_irqsave+0x1a/0x57 [ 20.254275] softirqs last enabled at (115966): [] irq_forced_thread_fn+0x35/0x40 [ 20.254275] softirqs last disabled at (115967): [] call_softirq+0x1c/0x30 [ 20.254275] [ 20.254275] other info that might help us debug this: [ 20.254275] Possible unsafe locking scenario: [ 20.254275] [ 20.254275] CPU0 [ 20.254275] ---- [ 20.254275] lock(&(&mapping->tree_lock)->rlock); [ 20.254275] [ 20.254275] lock(&(&mapping->tree_lock)->rlock); [ 20.254275] [ 20.254275] *** DEADLOCK *** [ 20.254275] [ 20.254275] no locks held by irq/45-ahci/47. [ 20.254275] [ 20.254275] stack backtrace: [ 20.254275] Pid: 47, comm: irq/45-ahci Not tainted 3.0.0-rc4-mmotm0622 #1 [ 20.254275] Call Trace: [ 20.254275] [] print_usage_bug+0x1f5/0x206 [ 20.254275] [] ? print_irq_inversion_bug.part.15+0x1ae/0x1ae [ 20.254275] [] mark_lock_irq+0x6f/0x120 [ 20.254275] [] mark_lock+0xaf/0x122 [ 20.254275] [] mark_irqflags+0x82/0x13e [ 20.254275] [] __lock_acquire+0x22b/0x3e2 [ 20.254275] [] ? test_clear_page_writeback+0x39/0xd3 [ 20.254275] [] lock_acquire+0x103/0x153 [ 20.254275] [] ? test_clear_page_writeback+0x39/0xd3 [ 20.254275] [] _raw_spin_lock_irqsave+0x44/0x57 [ 20.254275] [] ? test_clear_page_writeback+0x39/0xd3 [ 20.254275] [] ? __wake_up+0x1d/0x48 [ 20.254275] [] test_clear_page_writeback+0x39/0xd3 [ 20.254275] [] end_page_writeback+0x2a/0x4c [ 20.254275] [] end_buffer_async_write.part.14+0x122/0x154 [ 20.254275] [] ? trace_hardirqs_on_caller+0xfd/0x13b [ 20.254275] [] end_buffer_async_write+0x3e/0x47 [ 20.254275] [] end_bio_bh_io_sync+0x53/0x63 [ 20.254275] [] ? invalidate_inode_buffers+0x5c/0x5c [ 20.254275] [] bio_endio+0x28/0x2a [ 20.254275] [] dec_pending+0x190/0x1b2 [ 20.254275] [] clone_endio+0xa3/0xb0 [ 20.254275] [] bio_endio+0x28/0x2a [ 20.254275] [] dec_pending+0x190/0x1b2 [ 20.254275] [] clone_endio+0xa3/0xb0 [ 20.254275] [] bio_endio+0x28/0x2a [ 20.254275] [] crypt_dec_pending+0x75/0xa1 [ 20.254275] [] crypt_endio+0xba/0xc9 [ 20.254275] [] ? rcu_read_lock+0x35/0x35 [ 20.254275] [] bio_endio+0x28/0x2a [ 20.254275] [] req_bio_endio+0xc1/0xcd [ 20.254275] [] blk_update_request+0x15e/0x389 [ 20.254275] [] blk_update_bidi_request+0x20/0x90 [ 20.254275] [] blk_end_bidi_request+0x1a/0x58 [ 20.254275] [] blk_end_request+0xb/0xd [ 20.254275] [] scsi_io_completion+0x1cc/0x4c7 [ 20.254275] [] scsi_finish_command+0xab/0xb4 [ 20.254275] [] scsi_softirq_done+0xed/0xf6 [ 20.254275] [] blk_done_softirq+0x6c/0x80 [ 20.254275] [] __do_softirq+0x110/0x278 [ 20.254275] [] ? irq_thread_fn+0x37/0x37 [ 20.254275] [] call_softirq+0x1c/0x30 [ 20.254275] [] ? do_softirq+0x44/0xf1 [ 20.254275] [] _local_bh_enable_ip+0x12a/0x178 [ 20.254275] [] local_bh_enable+0xd/0xf [ 20.254275] [] irq_forced_thread_fn+0x35/0x40 [ 20.254275] [] irq_thread+0xf6/0x1c9 [ 20.254275] [] ? irq_finalize_oneshot+0xc9/0xc9 [ 20.254275] [] kthread+0x7f/0x87 [ 20.254275] [] kernel_thread_helper+0x4/0x10 [ 20.254275] [] ? retint_restore_args+0xe/0xe [ 20.254275] [] ? __init_kthread_worker+0x55/0x55 [ 20.254275] [] ? gs_change+0xb/0xb [ 20.820457] dracut: /dev/mapper/vg_blackice-root: clean, 18016/65536 files, 181204/262144 blocks [ 20.862866] dracut: Remounting /dev/mapper/vg_blackice-root with -o ro,quota,usrjquota=aquota.user,grpjquota=aquota.group,jqfmt=vfsv0 [ 20.886535] EXT4-fs (dm-3): mounted filesystem with ordered data mode. Opts: quota,usrjquota=aquota.user,grpjquota=aquota.group,jqfmt=vfsv0 [ 20.927228] dracut: Mounted root filesystem /dev/mapper/vg_blackice-root [ 21.147364] dracut: Switching root --==_Exmh_1308794391_4530P Content-Type: application/pgp-signature -----BEGIN PGP SIGNATURE----- Version: GnuPG v1.4.11 (GNU/Linux) Comment: Exmh version 2.5 07/13/2001 iD8DBQFOAp4XcC3lWbTT17ARAgWFAKCRZq9rBC3NoZdG5s2ygLNvX0brZgCgt3J6 oUh34jW5xrAfg/uxyonFZcY= =/c4E -----END PGP SIGNATURE----- --==_Exmh_1308794391_4530P--