BUG: spinlock lockup while performing FS operations

BUG: spinlock lockup while performing FS operations

am 06.10.2011 14:50:29 von paramonov

Hi!

Faced with this problem. There are RAID5, assembled by mdadm (/dev/md127),
which is divided into 2 partitions (md127p1 and md127p2). In both reiserfs. The
second partition is exported via NFS. Everything works, the array is intact and
fully synchronized. SMART says disks are healthy. But when copy too many files
all hangs and saves only the reset. After a reset of course runs fsck, and then
synchronize the array.

I have a brand new computer. Sleaze is not set. Motherboard gigabyte 870-UD3,
Power Supply FSP 700W, memory 16Gb Kingston, CPU Phenom II X6 1090T.

I reported an error on bugs.gentoo.org: https://bugs.gentoo.org/show_bug.cgi?id=385047
Was compiling a custom kernel with support for debugging and debug messages are received.
Duane Griffin then sent me upstream.

Now I have have BUG spinlock lockup on screen:

Nov 26 13:34:46 localhost kernel: BUG: spinlock lockup on CPU#2, mc/7609, ffff880419c37200
Oct 4 15:55:50 localhost kernel: BUG: spinlock lockup on CPU#3, flush-9:127/2391, ffff880419c37200

Full log from /var/log/messages:

Oct 4 15:53:09 localhost kernel: INFO: rcu_preempt_state detected stalls on CPUs/tasks: { 0 2} (detected by 5, t=60028 jiffies)
Oct 4 15:53:15 localhost kernel: INFO: rcu_bh_state detected stalls on CPUs/tasks: { 0 2 3} (detected by 5, t=60025 jiffies)
Oct 4 15:55:25 localhost kernel: INFO: task sync_supers:151 blocked for more than 120 seconds.
Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 4 15:55:25 localhost kernel: sync_supers D 0000000000000000 0 151 2 0x00000000
Oct 4 15:55:25 localhost kernel: ffff88042dba5740 0000000000000046 ffffffff81493e95 0000000000000008
Oct 4 15:55:25 localhost kernel: ffff88042dba8000 00000000000001ec 0000000000010b40 ffff88042dba8000
Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88042dba5fd8 ffff88042dba4000 0000000000004000
Oct 4 15:55:25 localhost kernel: Call Trace:
Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0xa10
Oct 4 15:55:25 localhost kernel: [] ? mark_held_locks+0x72/0xa0
Oct 4 15:55:25 localhost kernel: [] ? get_parent_ip+0x11/0x50
Oct 4 15:55:25 localhost kernel: [] get_active_stripe+0x312/0x6f0
Oct 4 15:55:25 localhost kernel: [] ? try_to_wake_up+0x2d0/0x2d0
Oct 4 15:55:25 localhost kernel: [] make_request+0x1a8/0x720
Oct 4 15:55:25 localhost kernel: [] ? wake_up_bit+0x40/0x40
Oct 4 15:55:25 localhost kernel: [] md_make_request+0x16e/0x2f0
Oct 4 15:55:25 localhost kernel: [] ? md_make_request+0x58/0x2f0
Oct 4 15:55:25 localhost kernel: [] ? kmem_cache_alloc+0x33/0xc0
Oct 4 15:55:25 localhost kernel: [] generic_make_request+0x14c/0x2f0
Oct 4 15:55:25 localhost kernel: [] submit_bio+0x61/0xd0
Oct 4 15:55:25 localhost kernel: [] submit_bh+0xe6/0x120
Oct 4 15:55:25 localhost kernel: [] write_ordered_chunk+0x5b/0x90
Oct 4 15:55:25 localhost kernel: [] add_to_chunk+0x4c/0x80
Oct 4 15:55:25 localhost kernel: [] ? add_to_chunk+0x80/0x80
Oct 4 15:55:25 localhost kernel: [] write_ordered_buffers.clone.31+0x8d/0x2a0
Oct 4 15:55:25 localhost kernel: [] ? trace_hardirqs_on+0xd/0x10
Oct 4 15:55:25 localhost kernel: [] flush_commit_list+0x1bf/0x6e0
Oct 4 15:55:25 localhost kernel: [] do_journal_end.clone.34+0xdb4/0xf20
Oct 4 15:55:25 localhost kernel: [] ? bdi_sched_wait+0x10/0x10
Oct 4 15:55:25 localhost kernel: [] journal_end_sync+0x64/0x70
Oct 4 15:55:25 localhost kernel: [] reiserfs_sync_fs+0x58/0x70
Oct 4 15:55:25 localhost kernel: [] ? down_read+0x2f/0x50
Oct 4 15:55:25 localhost kernel: [] reiserfs_write_super+0xe/0x10
Oct 4 15:55:25 localhost kernel: [] sync_supers+0xfa/0x100
Oct 4 15:55:25 localhost kernel: [] bdi_sync_supers+0x41/0x60
Oct 4 15:55:25 localhost kernel: [] ? bdi_sched_wait+0x10/0x10
Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
Oct 4 15:55:25 localhost kernel: [] kernel_thread_helper+0x4/0x10
Oct 4 15:55:25 localhost kernel: [] ? finish_task_switch+0x80/0x110
Oct 4 15:55:25 localhost kernel: [] ? retint_restore_args+0xe/0xe
Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_worker+0x70/0x70
Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
Oct 4 15:55:25 localhost kernel: 2 locks held by sync_supers/151:
Oct 4 15:55:25 localhost kernel: #0: (&type->s_umount_key#18){+++++.}, at: [] sync_supers+0x83/0x100
Oct 4 15:55:25 localhost kernel: #1: (&jl->j_commit_mutex){+.+...}, at: [] flush_commit_list+0x138/0x6e0
Oct 4 15:55:25 localhost kernel: INFO: task md127_resync:3773 blocked for more than 120 seconds.
Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 4 15:55:25 localhost kernel: md127_resync D 0000000000000000 0 3773 2 0x00000000
Oct 4 15:55:25 localhost kernel: ffff88041880fbb0 0000000000000046 ffffffff81493e95 0000000000000000
Oct 4 15:55:25 localhost kernel: 0000000000000000 ffff88041822e158 0000000000010b40 ffff88042d935b20
Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88041880ffd8 ffff88041880e000 0000000000004000
Oct 4 15:55:25 localhost kernel: Call Trace:
Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0xa10
Oct 4 15:55:25 localhost kernel: [] ? get_parent_ip+0x11/0x50
Oct 4 15:55:25 localhost kernel: [] schedule_timeout+0x152/0x220
Oct 4 15:55:25 localhost kernel: [] ? run_timer_softirq+0x2c0/0x2c0
Oct 4 15:55:25 localhost kernel: [] schedule_timeout_uninterruptible+0x19/0x20
Oct 4 15:55:25 localhost kernel: [] msleep+0x18/0x20
Oct 4 15:55:25 localhost kernel: [] md_do_sync+0x93c/0xd60
Oct 4 15:55:25 localhost kernel: [] ? _raw_spin_unlock_irq+0x2b/0x60
Oct 4 15:55:25 localhost kernel: [] ? wake_up_bit+0x40/0x40
Oct 4 15:55:25 localhost kernel: [] ? recalc_sigpending+0x16/0x40
Oct 4 15:55:25 localhost kernel: [] md_thread+0x116/0x150
Oct 4 15:55:25 localhost kernel: [] ? _raw_spin_unlock_irqrestore+0x3d/0x70
Oct 4 15:55:25 localhost kernel: [] ? md_register_thread+0x110/0x110
Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
Oct 4 15:55:25 localhost kernel: [] kernel_thread_helper+0x4/0x10
Oct 4 15:55:25 localhost kernel: [] ? finish_task_switch+0x80/0x110
Oct 4 15:55:25 localhost kernel: [] ? retint_restore_args+0xe/0xe
Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_worker+0x70/0x70
Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
Oct 4 15:55:25 localhost kernel: no locks held by md127_resync/3773.
Oct 4 15:55:25 localhost kernel: INFO: task mc:7609 blocked for more than 120 seconds.
Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 4 15:55:25 localhost kernel: mc D 00000000000213da 0 7609 7603 0x00000000
Oct 4 15:55:25 localhost kernel: 0000000091827364 ffff880418bb9af0 ffff880418bb9af0 ffff880418bb9b00
Oct 4 15:55:25 localhost kernel: ffff880418bb9b00 ffffffff00000000 0000000000000087 0000000000521e7f
Oct 4 15:55:25 localhost kernel: 00000000000000ca 00000000000000cb 0000000000000133 ffff880418bb9bd8
Oct 4 15:55:25 localhost kernel: Call Trace:
Oct 4 15:55:25 localhost kernel: [] ? reiserfs_readpages+0x18/0x20
Oct 4 15:55:25 localhost kernel: [] ? __do_page_cache_readahead+0x20d/0x2c0
Oct 4 15:55:25 localhost kernel: [] ? __do_page_cache_readahead+0xb5/0x2c0
Oct 4 15:55:25 localhost kernel: [] ? fbcon_decor_cursor+0x150/0x1e0
Oct 4 15:55:25 localhost kernel: [] ? ra_submit+0x1c/0x20
Oct 4 15:55:25 localhost kernel: [] ? ondemand_readahead+0x106/0x2b0
Oct 4 15:55:25 localhost kernel: [] ? page_cache_sync_readahead+0x2c/0x40
Oct 4 15:55:25 localhost kernel: [] ? generic_file_aio_read+0x428/0x770
Oct 4 15:55:25 localhost kernel: [] ? do_sync_read+0xd2/0x110
Oct 4 15:55:25 localhost kernel: [] ? security_file_permission+0x8c/0xa0
Oct 4 15:55:25 localhost kernel: [] ? vfs_read+0xc3/0x170
Oct 4 15:55:25 localhost kernel: [] ? sys_read+0x4c/0x90
Oct 4 15:55:25 localhost kernel: [] ? system_call_fastpath+0x16/0x1b
Oct 4 15:55:25 localhost kernel: 1 lock held by mc/7609:
Oct 4 15:55:25 localhost kernel: #0: (&(&conf->device_lock)->rlock){..-...}, at: [] release_stripe+0x32/0x60
Oct 4 15:55:25 localhost kernel: INFO: task kworker/1:2:7644 blocked for more than 120 seconds.
Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 4 15:55:25 localhost kernel: kworker/1:2 D 0000000000000000 0 7644 2 0x00000000
Oct 4 15:55:25 localhost kernel: ffff88041b761c50 0000000000000046 ffffffff81493e95 0000000000000002
Oct 4 15:55:25 localhost kernel: ffff88041b761c10 0000000000000046 0000000000010b40 ffff88041b57ad90
Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88041b761fd8 ffff88041b760000 0000000000004000
Oct 4 15:55:25 localhost kernel: Call Trace:
Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0xa10
Oct 4 15:55:25 localhost kernel: [] ? load_balance+0xd1/0x830
Oct 4 15:55:25 localhost kernel: [] ? mark_held_locks+0x72/0xa0
Oct 4 15:55:25 localhost kernel: [] mutex_lock_nested+0x167/0x380
Oct 4 15:55:25 localhost kernel: [] ? flush_commit_list+0x138/0x6e0
Oct 4 15:55:25 localhost kernel: [] ? trace_hardirqs_on_caller+0x12d/0x170
Oct 4 15:55:25 localhost kernel: [] flush_commit_list+0x138/0x6e0
Oct 4 15:55:25 localhost kernel: [] flush_async_commits+0x5a/0x70
Oct 4 15:55:25 localhost kernel: [] process_one_work+0x18b/0x440
Oct 4 15:55:25 localhost kernel: [] ? process_one_work+0x12a/0x440
Oct 4 15:55:25 localhost kernel: [] ? get_list_bitmap+0xc0/0xc0
Oct 4 15:55:25 localhost kernel: [] worker_thread+0x162/0x340
Oct 4 15:55:25 localhost kernel: [] ? manage_workers.clone.25+0x230/0x230
Oct 4 15:55:25 localhost kernel: [] ? manage_workers.clone.25+0x230/0x230
Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
Oct 4 15:55:25 localhost kernel: [] kernel_thread_helper+0x4/0x10
Oct 4 15:55:25 localhost kernel: [] ? finish_task_switch+0x80/0x110
Oct 4 15:55:25 localhost kernel: [] ? retint_restore_args+0xe/0xe
Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_worker+0x70/0x70
Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
Oct 4 15:55:25 localhost kernel: 3 locks held by kworker/1:2/7644:
Oct 4 15:55:25 localhost kernel: #0: (reiserfs){.+.+..}, at: [] process_one_work+0x12a/0x440
Oct 4 15:55:25 localhost kernel: #1: ((&(&journal->j_work)->work)){+.+...}, at: [] process_one_work+0x12a/0x440
Oct 4 15:55:25 localhost kernel: #2: (&jl->j_commit_mutex){+.+...}, at: [] flush_commit_list+0x138/0x6e0
Oct 4 15:55:25 localhost kernel: INFO: task flush-9:127:2391 blocked for more than 120 seconds.
Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Oct 4 15:55:25 localhost kernel: flush-9:127 D ffffffff8112b988 0 2391 2 0x00000000
Oct 4 15:55:25 localhost kernel: 0000000000000000 ffffffff81897e00 ffff8804184bd808 ffff880419c2c980
Oct 4 15:55:25 localhost kernel: ffff88040367fc80 ffff88042f019800 ffff880419c2c8e0 ffff880419c2c970
Oct 4 15:55:25 localhost kernel: ffff88040367fd00 ffff88042f019868 ffff88040367fcd0 ffffffff8112c4b3
Oct 4 15:55:25 localhost kernel: Call Trace:
Oct 4 15:55:25 localhost kernel: [] ? writeback_inodes_wb+0x83/0x180
Oct 4 15:55:25 localhost kernel: [] ? wb_writeback+0x2bb/0x330
Oct 4 15:55:25 localhost kernel: [] ? sub_preempt_count+0x95/0xd0
Oct 4 15:55:25 localhost kernel: [] ? wb_do_writeback+0x240/0x250
Oct 4 15:55:25 localhost kernel: [] ? bdi_writeback_thread+0x92/0x180
Oct 4 15:55:25 localhost kernel: [] ? wb_do_writeback+0x250/0x250
Oct 4 15:55:25 localhost kernel: [] ? kthread+0x96/0xa0
Oct 4 15:55:25 localhost kernel: [] ? kernel_thread_helper+0x4/0x10
Oct 4 15:55:25 localhost kernel: [] ? finish_task_switch+0x80/0x110
Oct 4 15:55:25 localhost kernel: [] ? retint_restore_args+0xe/0xe
Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_worker+0x70/0x70
Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
Oct 4 15:55:25 localhost kernel: 2 locks held by flush-9:127/2391:
Oct 4 15:55:25 localhost kernel: #0: (&type->s_umount_key#24){.+.+..}, at: [] writeback_inodes_wb+0xfc/0x180
Oct 4 15:55:25 localhost kernel: #1: (&(&conf->device_lock)->rlock){..-...}, at: [] get_active_stripe+0x35/0x6f0
Nov 26 13:34:46 localhost -- MARK --
Nov 26 13:34:46 localhost kernel: BUG: spinlock lockup on CPU#2, mc/7609, ffff880419c37200
Nov 26 13:34:46 localhost kernel: Pid: 7609, comm: mc Tainted: G W 3.0.4-gentoo-r1 #7
Nov 26 13:34:46 localhost kernel: Call Trace:
Nov 26 13:34:46 localhost kernel: [] do_raw_spin_lock+0x156/0x170
Nov 26 13:34:46 localhost kernel: [] _raw_spin_lock_irqsave+0x49/0x60
Nov 26 13:34:46 localhost kernel: [] ? release_stripe+0x32/0x60
Nov 26 13:34:46 localhost kernel: [] ? _raw_spin_unlock_irqrestore+0x3d/0x70
Nov 26 13:34:46 localhost kernel: [] release_stripe+0x32/0x60
Nov 26 13:34:46 localhost kernel: [] raid5_end_write_request+0xcf/0x120
Nov 26 13:34:46 localhost kernel: [] bio_endio+0x18/0x30
Nov 26 13:34:46 localhost syslog-ng[6446]: Log statistics; processed='center(received)=0', processed='center(queued)=0', processed='source(src)=999', processed='destination(console_all)=999', processed='destination(messages)=999', processed='global(payload_reallocs)=0', processed='global(sdata_updates)=0', processed='src.internal(src#1)=2', stamp='src.internal(src#1)=2584593286', processed='global(msg_clones)=0'
Nov 26 13:36:43 localhost kernel: [] req_bio_endio.clone.39+0x8b/0xd0
Nov 26 13:36:43 localhost kernel: [] blk_update_request+0xf3/0x500
Nov 26 13:36:43 localhost kernel: [] ? blk_update_request+0x329/0x500
Nov 26 13:36:43 localhost kernel: [] ? ata_scsi_qc_complete+0x65/0x460
Nov 26 13:36:43 localhost kernel: [] blk_update_bidi_request+0x2f/0x90
Nov 26 13:36:43 localhost kernel: [] blk_end_bidi_request+0x2a/0x80
Nov 26 13:36:43 localhost kernel: [] blk_end_request+0xb/0x10
Nov 26 13:36:43 localhost kernel: [] scsi_io_completion+0x97/0x5d0
Nov 26 13:36:43 localhost kernel: [] scsi_finish_command+0xb2/0xe0
Nov 26 13:36:43 localhost kernel: [] scsi_softirq_done+0x9d/0x130
Oct 4 15:55:50 localhost kernel: [] blk_done_softirq+0x7d/0x90
Oct 4 15:55:50 localhost kernel: [] __do_softirq+0xa8/0x140
Oct 4 15:55:50 localhost kernel: [] call_softirq+0x1c/0x30
Oct 4 15:55:50 localhost kernel: [] do_softirq+0x85/0xc0
Oct 4 15:55:50 localhost kernel: [] irq_exit+0x9e/0xc0
Oct 4 15:55:50 localhost kernel: [] do_IRQ+0x61/0xd0
Oct 4 15:55:50 localhost kernel: [] common_interrupt+0x13/0x13
Oct 4 15:55:50 localhost kernel: [] ? _raw_spin_unlock_irq+0x31/0x60
Oct 4 15:55:50 localhost kernel: [] ? _raw_spin_unlock_irq+0x2b/0x60
Oct 4 15:55:50 localhost kernel: [] scsi_request_fn+0x34e/0x400
Oct 4 15:55:50 localhost kernel: [] __blk_run_queue+0x19/0x20
Oct 4 15:55:50 localhost kernel: [] cfq_insert_request+0x345/0x4d0
Oct 4 15:55:50 localhost kernel: [] __elv_add_request+0x126/0x1e0
Oct 4 15:55:50 localhost kernel: [] blk_flush_plug_list+0x1b0/0x200
Oct 4 15:55:50 localhost kernel: [] schedule+0x432/0xa10
Oct 4 15:55:50 localhost kernel: [] ? get_parent_ip+0x11/0x50
Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_count+0x95/0xd0
Oct 4 15:55:50 localhost kernel: [] get_active_stripe+0x312/0x6f0
Oct 4 15:55:50 localhost kernel: [] ? try_to_wake_up+0x2d0/0x2d0
Oct 4 15:55:50 localhost kernel: [] make_request+0x1a8/0x720
Oct 4 15:55:50 localhost kernel: [] ? wake_up_bit+0x40/0x40
Oct 4 15:55:50 localhost kernel: [] md_make_request+0x16e/0x2f0
Oct 4 15:55:50 localhost kernel: [] ? md_make_request+0x58/0x2f0
Oct 4 15:55:50 localhost kernel: [] generic_make_request+0x14c/0x2f0
Oct 4 15:55:50 localhost kernel: [] ? bvec_alloc_bs+0x6a/0x100
Oct 4 15:55:50 localhost kernel: [] submit_bio+0x61/0xd0
Oct 4 15:55:50 localhost kernel: [] do_mpage_readpage+0x317/0x650
Oct 4 15:55:50 localhost kernel: [] ? __lru_cache_add+0x76/0xc0
Oct 4 15:55:50 localhost kernel: [] mpage_readpages+0xfc/0x150
Oct 4 15:55:50 localhost kernel: [] ? restart_transaction+0xb0/0xb0
Oct 4 15:55:50 localhost kernel: [] ? restart_transaction+0xb0/0xb0
Oct 4 15:55:50 localhost kernel: [] reiserfs_readpages+0x18/0x20
Oct 4 15:55:50 localhost kernel: [] __do_page_cache_readahead+0x20d/0x2c0
Oct 4 15:55:50 localhost kernel: [] ? __do_page_cache_readahead+0xb5/0x2c0
Oct 4 15:55:50 localhost kernel: [] ? fbcon_decor_cursor+0x150/0x1e0
Oct 4 15:55:50 localhost kernel: [] ra_submit+0x1c/0x20
Oct 4 15:55:50 localhost kernel: [] ondemand_readahead+0x106/0x2b0
Oct 4 15:55:50 localhost kernel: [] page_cache_sync_readahead+0x2c/0x40
Oct 4 15:55:50 localhost kernel: [] generic_file_aio_read+0x428/0x770
Oct 4 15:55:50 localhost kernel: [] do_sync_read+0xd2/0x110
Oct 4 15:55:50 localhost kernel: [] ? security_file_permission+0x8c/0xa0
Oct 4 15:55:50 localhost kernel: [] vfs_read+0xc3/0x170
Oct 4 15:55:50 localhost kernel: [] sys_read+0x4c/0x90
Oct 4 15:55:50 localhost kernel: [] system_call_fastpath+0x16/0x1b
Oct 4 15:55:50 localhost kernel: BUG: spinlock lockup on CPU#3, flush-9:127/2391, ffff880419c37200
Oct 4 15:55:50 localhost kernel: Pid: 2391, comm: flush-9:127 Tainted: G W 3.0.4-gentoo-r1 #7
Oct 4 15:55:50 localhost kernel: Call Trace:
Oct 4 15:55:50 localhost kernel: [] do_raw_spin_lock+0x156/0x170
Oct 4 15:55:50 localhost kernel: [] _raw_spin_lock_irq+0x44/0x50
Oct 4 15:55:50 localhost kernel: [] ? get_active_stripe+0x35/0x6f0
Oct 4 15:55:50 localhost kernel: [] get_active_stripe+0x35/0x6f0
Oct 4 15:55:50 localhost kernel: [] ? mark_held_locks+0x72/0xa0
Oct 4 15:55:50 localhost kernel: [] ? get_parent_ip+0x11/0x50
Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_count+0x95/0xd0
Oct 4 15:55:50 localhost kernel: [] ? _raw_spin_unlock_irqrestore+0x3d/0x70
Oct 4 15:55:50 localhost kernel: [] ? prepare_to_wait+0x5b/0x90
Oct 4 15:55:50 localhost kernel: [] make_request+0x1a8/0x720
Oct 4 15:55:50 localhost kernel: [] ? wake_up_bit+0x40/0x40
Oct 4 15:55:50 localhost kernel: [] md_make_request+0x16e/0x2f0
Oct 4 15:55:50 localhost kernel: [] ? md_make_request+0x58/0x2f0
Oct 4 15:55:50 localhost kernel: [] ? kmem_cache_alloc+0x33/0xc0
Oct 4 15:55:50 localhost kernel: [] generic_make_request+0x14c/0x2f0
Oct 4 15:55:50 localhost kernel: [] submit_bio+0x61/0xd0
Oct 4 15:55:50 localhost kernel: [] submit_bh+0xe6/0x120
Oct 4 15:55:50 localhost kernel: [] __block_write_full_page+0x1f7/0x370
Oct 4 15:55:50 localhost kernel: [] ? block_read_full_page+0x3b0/0x3b0
Oct 4 15:55:50 localhost kernel: [] ? I_BDEV+0x10/0x10
Oct 4 15:55:50 localhost kernel: [] ? I_BDEV+0x10/0x10
Oct 4 15:55:50 localhost kernel: [] block_write_full_page_endio+0xee/0x130
Oct 4 15:55:50 localhost kernel: [] ? mark_held_locks+0x72/0xa0
Oct 4 15:55:50 localhost kernel: [] block_write_full_page+0x10/0x20
Oct 4 15:55:50 localhost kernel: [] blkdev_writepage+0x13/0x20
Oct 4 15:55:50 localhost kernel: [] __writepage+0x15/0x50
Oct 4 15:55:50 localhost kernel: [] write_cache_pages+0x1f1/0x420
Oct 4 15:55:50 localhost kernel: [] ? set_page_dirty+0x70/0x70
Oct 4 15:55:50 localhost kernel: [] generic_writepages+0x48/0x60
Oct 4 15:55:50 localhost kernel: [] do_writepages+0x1f/0x40
Oct 4 15:55:50 localhost kernel: [] writeback_single_inode+0xf9/0x260
Oct 4 15:55:50 localhost kernel: [] writeback_sb_inodes+0xe8/0x1c0
Oct 4 15:55:50 localhost kernel: [] writeback_inodes_wb+0x83/0x180
Oct 4 15:55:50 localhost kernel: [] wb_writeback+0x2bb/0x330
Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_count+0x95/0xd0
Oct 4 15:55:50 localhost kernel: [] wb_do_writeback+0x240/0x250
Oct 4 15:55:50 localhost kernel: [] bdi_writeback_thread+0x92/0x180
Oct 4 15:55:50 localhost kernel: [] ? wb_do_writeback+0x250/0x250
Oct 4 15:55:50 localhost kernel: [] kthread+0x96/0xa0
Oct 4 15:55:50 localhost kernel: [] kernel_thread_helper+0x4/0x10
Oct 4 15:55:50 localhost kernel: [] ? finish_task_switch+0x80/0x110
Oct 4 15:55:50 localhost kernel: [] ? retint_restore_args+0xe/0xe
Oct 4 15:55:50 localhost kernel: [] ? __init_kthread_worker+0x70/0x70
Oct 4 15:55:50 localhost kernel: [] ? gs_change+0xb/0xb

Why date a failure to report?What next?
Thanks.

---
ParamonovValery.

Re: BUG: spinlock lockup while performing FS operations

am 07.10.2011 02:39:03 von dan.j.williams

On Thu, Oct 6, 2011 at 5:50 AM, ÷ÁÌÅÒÉ=CA ru> wrote:
> Hi!
>
> Faced with this problem. There are RAID5, assembled by mdadm (/dev/md=
127),
> which is divided into 2 partitions (md127p1 and md127p2). In both rei=
serfs.
> The
> second partition is exported via NFS. Everything works, the array is =
intact
> and
> fully synchronized. SMART says disks are healthy. But when copy too m=
any
> files
> all hangs and saves only the reset. After a reset of course runs fsck=
, and
> then
> synchronize the array.
>
> I have a brand new computer. Sleaze is not set. Motherboard gigabyte
> 870-UD3,
> Power Supply FSP 700W, memory 16Gb Kingston, CPU Phenom II X6 1090T.
>
> I =9Areported an error =9Aon =9Abugs.gentoo.org:
> https://bugs.gentoo.org/show_bug.cgi?id=3D385047
> Was =9Acompiling a custom kernel =9Awith support for =9Adebugging and=
=9Adebug
> messages are =9Areceived.
> Duane Griffin =9Athen =9Asent me =9Aupstream.
>
> Now I have have BUG spinlock lockup on screen:
>
> Nov 26 13:34:46 localhost kernel: BUG: spinlock lockup on CPU#2, mc/7=
609,
> ffff880419c37200
> Oct =9A4 15:55:50 localhost kernel: BUG: spinlock lockup on CPU#3,
> flush-9:127/2391, ffff880419c37200
>
> Full log from /var/log/messages:

This is the full log? I see other /var/log/messages excerpts from the
gentoo bugzilla. Just wondering if there were any other warnings in
the log that precede the failure?

Can you attach the kernel configuration file to that bugzilla as well.

It sounds like you can reproduce it reliably. Is this a recent
upgrade, or a new install? If it was working before an upgrade we
might be able to bisect.

--
Dan

Re: BUG: spinlock lockup while performing FS operations

am 07.10.2011 03:14:10 von NeilBrown

--Sig_/hNgepwMnoJReQeP6W6us2Op
Content-Type: text/plain; charset=UTF-8
Content-Transfer-Encoding: quoted-printable

On Thu, 06 Oct 2011 19:50:29 +0700 Валери=D0=
=B9 wrote:

> Hi!
>=20
> Faced with this problem. There are RAID5, assembled by mdadm (/dev/md127),
> which is divided into 2 partitions (md127p1 and md127p2). In both reiserf=
s. The
> second partition is exported via NFS. Everything works, the array is inta=
ct and
> fully synchronized. SMART says disks are healthy. But when copy too many =
files
> all hangs and saves only the reset. After a reset of course runs fsck, an=
d then
> synchronize the array.
>=20
> I have a brand new computer. Sleaze is not set. Motherboard gigabyte 870-=
UD3,
> Power Supply FSP 700W, memory 16Gb Kingston, CPU Phenom II X6 1090T.
>=20
> I reported an error on bugs.gentoo.org: https://bugs.gentoo.org/show_b=
ug.cgi?id=3D385047
> Was compiling a custom kernel with support for debugging and debug me=
ssages are received.
> Duane Griffin then sent me upstream.
>=20
> Now I have have BUG spinlock lockup on screen:
>=20
> Nov 26 13:34:46 localhost kernel: BUG: spinlock lockup on CPU#2, mc/7609,=
ffff880419c37200
> Oct 4 15:55:50 localhost kernel: BUG: spinlock lockup on CPU#3, flush-9:=
127/2391, ffff880419c37200

Nov 26 ???
Why are there dates from last year in the middle of you log? Have you
edited the log at all, or joined different bits together??


Please make sure that you provide complete logs, including where possible a
few lines before and after the bit that you think is important.

If the clock is really jumping around, then maybe that is confusing some
timing for the measuring of whether a task has 'hung' or not.

Can you get a complete trace without any sudden changes in the system time?

NeilBrown



>=20
> Full log from /var/log/messages:
>=20
> Oct 4 15:53:09 localhost kernel: INFO: rcu_preempt_state detected stalls=
on CPUs/tasks: { 0 2} (detected by 5, t=3D60028 jiffies)
> Oct 4 15:53:15 localhost kernel: INFO: rcu_bh_state detected stalls on C=
PUs/tasks: { 0 2 3} (detected by 5, t=3D60025 jiffies)
> Oct 4 15:55:25 localhost kernel: INFO: task sync_supers:151 blocked for =
more than 120 seconds.
> Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_ti=
meout_secs" disables this message.
> Oct 4 15:55:25 localhost kernel: sync_supers D 0000000000000000 =
0 151 2 0x00000000
> Oct 4 15:55:25 localhost kernel: ffff88042dba5740 0000000000000046 fffff=
fff81493e95 0000000000000008
> Oct 4 15:55:25 localhost kernel: ffff88042dba8000 00000000000001ec 00000=
00000010b40 ffff88042dba8000
> Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88042dba5fd8 ffff8=
8042dba4000 0000000000004000
> Oct 4 15:55:25 localhost kernel: Call Trace:
> Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0=
xa10
> Oct 4 15:55:25 localhost kernel: [] ? mark_held_locks+=
0x72/0xa0
> Oct 4 15:55:25 localhost kernel: [] ? get_parent_ip+0x=
11/0x50
> Oct 4 15:55:25 localhost kernel: [] get_active_stripe+=
0x312/0x6f0
> Oct 4 15:55:25 localhost kernel: [] ? try_to_wake_up+0=
x2d0/0x2d0
> Oct 4 15:55:25 localhost kernel: [] make_request+0x1a8=
/0x720
> Oct 4 15:55:25 localhost kernel: [] ? wake_up_bit+0x40=
/0x40
> Oct 4 15:55:25 localhost kernel: [] md_make_request+0x=
16e/0x2f0
> Oct 4 15:55:25 localhost kernel: [] ? md_make_request+=
0x58/0x2f0
> Oct 4 15:55:25 localhost kernel: [] ? kmem_cache_alloc=
+0x33/0xc0
> Oct 4 15:55:25 localhost kernel: [] generic_make_reque=
st+0x14c/0x2f0
> Oct 4 15:55:25 localhost kernel: [] submit_bio+0x61/0x=
d0
> Oct 4 15:55:25 localhost kernel: [] submit_bh+0xe6/0x1=
20
> Oct 4 15:55:25 localhost kernel: [] write_ordered_chun=
k+0x5b/0x90
> Oct 4 15:55:25 localhost kernel: [] add_to_chunk+0x4c/=
0x80
> Oct 4 15:55:25 localhost kernel: [] ? add_to_chunk+0x8=
0/0x80
> Oct 4 15:55:25 localhost kernel: [] write_ordered_buff=
ers.clone.31+0x8d/0x2a0
> Oct 4 15:55:25 localhost kernel: [] ? trace_hardirqs_o=
n+0xd/0x10
> Oct 4 15:55:25 localhost kernel: [] flush_commit_list+=
0x1bf/0x6e0
> Oct 4 15:55:25 localhost kernel: [] do_journal_end.clo=
ne.34+0xdb4/0xf20
> Oct 4 15:55:25 localhost kernel: [] ? bdi_sched_wait+0=
x10/0x10
> Oct 4 15:55:25 localhost kernel: [] journal_end_sync+0=
x64/0x70
> Oct 4 15:55:25 localhost kernel: [] reiserfs_sync_fs+0=
x58/0x70
> Oct 4 15:55:25 localhost kernel: [] ? down_read+0x2f/0=
x50
> Oct 4 15:55:25 localhost kernel: [] reiserfs_write_sup=
er+0xe/0x10
> Oct 4 15:55:25 localhost kernel: [] sync_supers+0xfa/0=
x100
> Oct 4 15:55:25 localhost kernel: [] bdi_sync_supers+0x=
41/0x60
> Oct 4 15:55:25 localhost kernel: [] ? bdi_sched_wait+0=
x10/0x10
> Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
> Oct 4 15:55:25 localhost kernel: [] kernel_thread_help=
er+0x4/0x10
> Oct 4 15:55:25 localhost kernel: [] ? finish_task_swit=
ch+0x80/0x110
> Oct 4 15:55:25 localhost kernel: [] ? retint_restore_a=
rgs+0xe/0xe
> Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_w=
orker+0x70/0x70
> Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
> Oct 4 15:55:25 localhost kernel: 2 locks held by sync_supers/151:
> Oct 4 15:55:25 localhost kernel: #0: (&type->s_umount_key#18){+++++.}, =
at: [] sync_supers+0x83/0x100
> Oct 4 15:55:25 localhost kernel: #1: (&jl->j_commit_mutex){+.+...}, at:=
[] flush_commit_list+0x138/0x6e0
> Oct 4 15:55:25 localhost kernel: INFO: task md127_resync:3773 blocked fo=
r more than 120 seconds.
> Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_ti=
meout_secs" disables this message.
> Oct 4 15:55:25 localhost kernel: md127_resync D 0000000000000000 =
0 3773 2 0x00000000
> Oct 4 15:55:25 localhost kernel: ffff88041880fbb0 0000000000000046 fffff=
fff81493e95 0000000000000000
> Oct 4 15:55:25 localhost kernel: 0000000000000000 ffff88041822e158 00000=
00000010b40 ffff88042d935b20
> Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88041880ffd8 ffff8=
8041880e000 0000000000004000
> Oct 4 15:55:25 localhost kernel: Call Trace:
> Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0=
xa10
> Oct 4 15:55:25 localhost kernel: [] ? get_parent_ip+0x=
11/0x50
> Oct 4 15:55:25 localhost kernel: [] schedule_timeout+0=
x152/0x220
> Oct 4 15:55:25 localhost kernel: [] ? run_timer_softir=
q+0x2c0/0x2c0
> Oct 4 15:55:25 localhost kernel: [] schedule_timeout_u=
ninterruptible+0x19/0x20
> Oct 4 15:55:25 localhost kernel: [] msleep+0x18/0x20
> Oct 4 15:55:25 localhost kernel: [] md_do_sync+0x93c/0=
xd60
> Oct 4 15:55:25 localhost kernel: [] ? _raw_spin_unlock=
_irq+0x2b/0x60
> Oct 4 15:55:25 localhost kernel: [] ? wake_up_bit+0x40=
/0x40
> Oct 4 15:55:25 localhost kernel: [] ? recalc_sigpendin=
g+0x16/0x40
> Oct 4 15:55:25 localhost kernel: [] md_thread+0x116/0x=
150
> Oct 4 15:55:25 localhost kernel: [] ? _raw_spin_unlock=
_irqrestore+0x3d/0x70
> Oct 4 15:55:25 localhost kernel: [] ? md_register_thre=
ad+0x110/0x110
> Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
> Oct 4 15:55:25 localhost kernel: [] kernel_thread_help=
er+0x4/0x10
> Oct 4 15:55:25 localhost kernel: [] ? finish_task_swit=
ch+0x80/0x110
> Oct 4 15:55:25 localhost kernel: [] ? retint_restore_a=
rgs+0xe/0xe
> Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_w=
orker+0x70/0x70
> Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
> Oct 4 15:55:25 localhost kernel: no locks held by md127_resync/3773.
> Oct 4 15:55:25 localhost kernel: INFO: task mc:7609 blocked for more tha=
n 120 seconds.
> Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_ti=
meout_secs" disables this message.
> Oct 4 15:55:25 localhost kernel: mc D 00000000000213da =
0 7609 7603 0x00000000
> Oct 4 15:55:25 localhost kernel: 0000000091827364 ffff880418bb9af0 ffff8=
80418bb9af0 ffff880418bb9b00
> Oct 4 15:55:25 localhost kernel: ffff880418bb9b00 ffffffff00000000 00000=
00000000087 0000000000521e7f
> Oct 4 15:55:25 localhost kernel: 00000000000000ca 00000000000000cb 00000=
00000000133 ffff880418bb9bd8
> Oct 4 15:55:25 localhost kernel: Call Trace:
> Oct 4 15:55:25 localhost kernel: [] ? reiserfs_readpag=
es+0x18/0x20
> Oct 4 15:55:25 localhost kernel: [] ? __do_page_cache_=
readahead+0x20d/0x2c0
> Oct 4 15:55:25 localhost kernel: [] ? __do_page_cache_=
readahead+0xb5/0x2c0
> Oct 4 15:55:25 localhost kernel: [] ? fbcon_decor_curs=
or+0x150/0x1e0
> Oct 4 15:55:25 localhost kernel: [] ? ra_submit+0x1c/0=
x20
> Oct 4 15:55:25 localhost kernel: [] ? ondemand_readahe=
ad+0x106/0x2b0
> Oct 4 15:55:25 localhost kernel: [] ? page_cache_sync_=
readahead+0x2c/0x40
> Oct 4 15:55:25 localhost kernel: [] ? generic_file_aio=
_read+0x428/0x770
> Oct 4 15:55:25 localhost kernel: [] ? do_sync_read+0xd=
2/0x110
> Oct 4 15:55:25 localhost kernel: [] ? security_file_pe=
rmission+0x8c/0xa0
> Oct 4 15:55:25 localhost kernel: [] ? vfs_read+0xc3/0x=
170
> Oct 4 15:55:25 localhost kernel: [] ? sys_read+0x4c/0x=
90
> Oct 4 15:55:25 localhost kernel: [] ? system_call_fast=
path+0x16/0x1b
> Oct 4 15:55:25 localhost kernel: 1 lock held by mc/7609:
> Oct 4 15:55:25 localhost kernel: #0: (&(&conf->device_lock)->rlock){..-=
....}, at: [] release_stripe+0x32/0x60
> Oct 4 15:55:25 localhost kernel: INFO: task kworker/1:2:7644 blocked for=
more than 120 seconds.
> Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_ti=
meout_secs" disables this message.
> Oct 4 15:55:25 localhost kernel: kworker/1:2 D 0000000000000000 =
0 7644 2 0x00000000
> Oct 4 15:55:25 localhost kernel: ffff88041b761c50 0000000000000046 fffff=
fff81493e95 0000000000000002
> Oct 4 15:55:25 localhost kernel: ffff88041b761c10 0000000000000046 00000=
00000010b40 ffff88041b57ad90
> Oct 4 15:55:25 localhost kernel: 0000000000010b40 ffff88041b761fd8 ffff8=
8041b760000 0000000000004000
> Oct 4 15:55:25 localhost kernel: Call Trace:
> Oct 4 15:55:25 localhost kernel: [] ? schedule+0x695/0=
xa10
> Oct 4 15:55:25 localhost kernel: [] ? load_balance+0xd=
1/0x830
> Oct 4 15:55:25 localhost kernel: [] ? mark_held_locks+=
0x72/0xa0
> Oct 4 15:55:25 localhost kernel: [] mutex_lock_nested+=
0x167/0x380
> Oct 4 15:55:25 localhost kernel: [] ? flush_commit_lis=
t+0x138/0x6e0
> Oct 4 15:55:25 localhost kernel: [] ? trace_hardirqs_o=
n_caller+0x12d/0x170
> Oct 4 15:55:25 localhost kernel: [] flush_commit_list+=
0x138/0x6e0
> Oct 4 15:55:25 localhost kernel: [] flush_async_commit=
s+0x5a/0x70
> Oct 4 15:55:25 localhost kernel: [] process_one_work+0=
x18b/0x440
> Oct 4 15:55:25 localhost kernel: [] ? process_one_work=
+0x12a/0x440
> Oct 4 15:55:25 localhost kernel: [] ? get_list_bitmap+=
0xc0/0xc0
> Oct 4 15:55:25 localhost kernel: [] worker_thread+0x16=
2/0x340
> Oct 4 15:55:25 localhost kernel: [] ? manage_workers.c=
lone.25+0x230/0x230
> Oct 4 15:55:25 localhost kernel: [] ? manage_workers.c=
lone.25+0x230/0x230
> Oct 4 15:55:25 localhost kernel: [] kthread+0x96/0xa0
> Oct 4 15:55:25 localhost kernel: [] kernel_thread_help=
er+0x4/0x10
> Oct 4 15:55:25 localhost kernel: [] ? finish_task_swit=
ch+0x80/0x110
> Oct 4 15:55:25 localhost kernel: [] ? retint_restore_a=
rgs+0xe/0xe
> Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_w=
orker+0x70/0x70
> Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
> Oct 4 15:55:25 localhost kernel: 3 locks held by kworker/1:2/7644:
> Oct 4 15:55:25 localhost kernel: #0: (reiserfs){.+.+..}, at: [ 8105cd6a>] process_one_work+0x12a/0x440
> Oct 4 15:55:25 localhost kernel: #1: ((&(&journal->j_work)->work)){+.+.=
...}, at: [] process_one_work+0x12a/0x440
> Oct 4 15:55:25 localhost kernel: #2: (&jl->j_commit_mutex){+.+...}, at:=
[] flush_commit_list+0x138/0x6e0
> Oct 4 15:55:25 localhost kernel: INFO: task flush-9:127:2391 blocked for=
more than 120 seconds.
> Oct 4 15:55:25 localhost kernel: "echo 0> /proc/sys/kernel/hung_task_ti=
meout_secs" disables this message.
> Oct 4 15:55:25 localhost kernel: flush-9:127 D ffffffff8112b988 =
0 2391 2 0x00000000
> Oct 4 15:55:25 localhost kernel: 0000000000000000 ffffffff81897e00 ffff8=
804184bd808 ffff880419c2c980
> Oct 4 15:55:25 localhost kernel: ffff88040367fc80 ffff88042f019800 ffff8=
80419c2c8e0 ffff880419c2c970
> Oct 4 15:55:25 localhost kernel: ffff88040367fd00 ffff88042f019868 ffff8=
8040367fcd0 ffffffff8112c4b3
> Oct 4 15:55:25 localhost kernel: Call Trace:
> Oct 4 15:55:25 localhost kernel: [] ? writeback_inodes=
_wb+0x83/0x180
> Oct 4 15:55:25 localhost kernel: [] ? wb_writeback+0x2=
bb/0x330
> Oct 4 15:55:25 localhost kernel: [] ? sub_preempt_coun=
t+0x95/0xd0
> Oct 4 15:55:25 localhost kernel: [] ? wb_do_writeback+=
0x240/0x250
> Oct 4 15:55:25 localhost kernel: [] ? bdi_writeback_th=
read+0x92/0x180
> Oct 4 15:55:25 localhost kernel: [] ? wb_do_writeback+=
0x250/0x250
> Oct 4 15:55:25 localhost kernel: [] ? kthread+0x96/0xa0
> Oct 4 15:55:25 localhost kernel: [] ? kernel_thread_he=
lper+0x4/0x10
> Oct 4 15:55:25 localhost kernel: [] ? finish_task_swit=
ch+0x80/0x110
> Oct 4 15:55:25 localhost kernel: [] ? retint_restore_a=
rgs+0xe/0xe
> Oct 4 15:55:25 localhost kernel: [] ? __init_kthread_w=
orker+0x70/0x70
> Oct 4 15:55:25 localhost kernel: [] ? gs_change+0xb/0xb
> Oct 4 15:55:25 localhost kernel: 2 locks held by flush-9:127/2391:
> Oct 4 15:55:25 localhost kernel: #0: (&type->s_umount_key#24){.+.+..}, =
at: [] writeback_inodes_wb+0xfc/0x180
> Oct 4 15:55:25 localhost kernel: #1: (&(&conf->device_lock)->rlock){..-=
....}, at: [] get_active_stripe+0x35/0x6f0
> Nov 26 13:34:46 localhost -- MARK --
> Nov 26 13:34:46 localhost kernel: BUG: spinlock lockup on CPU#2, mc/7609,=
ffff880419c37200
> Nov 26 13:34:46 localhost kernel: Pid: 7609, comm: mc Tainted: G W=
3.0.4-gentoo-r1 #7
> Nov 26 13:34:46 localhost kernel: Call Trace:
> Nov 26 13:34:46 localhost kernel: [] do_raw_spin=
_lock+0x156/0x170
> Nov 26 13:34:46 localhost kernel: [] _raw_spin_lock_irq=
save+0x49/0x60
> Nov 26 13:34:46 localhost kernel: [] ? release_stripe+0=
x32/0x60
> Nov 26 13:34:46 localhost kernel: [] ? _raw_spin_unlock=
_irqrestore+0x3d/0x70
> Nov 26 13:34:46 localhost kernel: [] release_stripe+0x3=
2/0x60
> Nov 26 13:34:46 localhost kernel: [] raid5_end_write_re=
quest+0xcf/0x120
> Nov 26 13:34:46 localhost kernel: [] bio_endio+0x18/0x30
> Nov 26 13:34:46 localhost syslog-ng[6446]: Log statistics; processed=3D'c=
enter(received)=3D0', processed=3D'center(queued)=3D0', processed=3D'source=
(src)=3D999', processed=3D'destination(console_all)=3D999', processed=3D'de=
stination(messages)=3D999', processed=3D'global(payload_reallocs)=3D0', pro=
cessed=3D'global(sdata_updates)=3D0', processed=3D'src.internal(src#1)=3D2'=
, stamp=3D'src.internal(src#1)=3D2584593286', processed=3D'global(msg_clone=
s)=3D0'
> Nov 26 13:36:43 localhost kernel: [] req_bio_endio.clon=
e.39+0x8b/0xd0
> Nov 26 13:36:43 localhost kernel: [] blk_update_request=
+0xf3/0x500
> Nov 26 13:36:43 localhost kernel: [] ? blk_update_reque=
st+0x329/0x500
> Nov 26 13:36:43 localhost kernel: [] ? ata_scsi_qc_comp=
lete+0x65/0x460
> Nov 26 13:36:43 localhost kernel: [] blk_update_bidi_re=
quest+0x2f/0x90
> Nov 26 13:36:43 localhost kernel: [] blk_end_bidi_reque=
st+0x2a/0x80
> Nov 26 13:36:43 localhost kernel: [] blk_end_request+0x=
b/0x10
> Nov 26 13:36:43 localhost kernel: [] scsi_io_completion=
+0x97/0x5d0
> Nov 26 13:36:43 localhost kernel: [] scsi_finish_comman=
d+0xb2/0xe0
> Nov 26 13:36:43 localhost kernel: [] scsi_softirq_done+=
0x9d/0x130
> Oct 4 15:55:50 localhost kernel: [] blk_done_softirq+0=
x7d/0x90
> Oct 4 15:55:50 localhost kernel: [] __do_softirq+0xa8/=
0x140
> Oct 4 15:55:50 localhost kernel: [] call_softirq+0x1c/=
0x30
> Oct 4 15:55:50 localhost kernel: [] do_softirq+0x85/0x=
c0
> Oct 4 15:55:50 localhost kernel: [] irq_exit+0x9e/0xc0
> Oct 4 15:55:50 localhost kernel: [] do_IRQ+0x61/0xd0
> Oct 4 15:55:50 localhost kernel: [] common_interrupt+0=
x13/0x13
> Oct 4 15:55:50 localhost kernel: [] ? _raw_spin=
_unlock_irq+0x31/0x60
> Oct 4 15:55:50 localhost kernel: [] ? _raw_spin_unlock=
_irq+0x2b/0x60
> Oct 4 15:55:50 localhost kernel: [] scsi_request_fn+0x=
34e/0x400
> Oct 4 15:55:50 localhost kernel: [] __blk_run_queue+0x=
19/0x20
> Oct 4 15:55:50 localhost kernel: [] cfq_insert_request=
+0x345/0x4d0
> Oct 4 15:55:50 localhost kernel: [] __elv_add_request+=
0x126/0x1e0
> Oct 4 15:55:50 localhost kernel: [] blk_flush_plug_lis=
t+0x1b0/0x200
> Oct 4 15:55:50 localhost kernel: [] schedule+0x432/0xa=
10
> Oct 4 15:55:50 localhost kernel: [] ? get_parent_ip+0x=
11/0x50
> Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_coun=
t+0x95/0xd0
> Oct 4 15:55:50 localhost kernel: [] get_active_stripe+=
0x312/0x6f0
> Oct 4 15:55:50 localhost kernel: [] ? try_to_wake_up+0=
x2d0/0x2d0
> Oct 4 15:55:50 localhost kernel: [] make_request+0x1a8=
/0x720
> Oct 4 15:55:50 localhost kernel: [] ? wake_up_bit+0x40=
/0x40
> Oct 4 15:55:50 localhost kernel: [] md_make_request+0x=
16e/0x2f0
> Oct 4 15:55:50 localhost kernel: [] ? md_make_request+=
0x58/0x2f0
> Oct 4 15:55:50 localhost kernel: [] generic_make_reque=
st+0x14c/0x2f0
> Oct 4 15:55:50 localhost kernel: [] ? bvec_alloc_bs+0x=
6a/0x100
> Oct 4 15:55:50 localhost kernel: [] submit_bio+0x61/0x=
d0
> Oct 4 15:55:50 localhost kernel: [] do_mpage_readpage+=
0x317/0x650
> Oct 4 15:55:50 localhost kernel: [] ? __lru_cache_add+=
0x76/0xc0
> Oct 4 15:55:50 localhost kernel: [] mpage_readpages+0x=
fc/0x150
> Oct 4 15:55:50 localhost kernel: [] ? restart_transact=
ion+0xb0/0xb0
> Oct 4 15:55:50 localhost kernel: [] ? restart_transact=
ion+0xb0/0xb0
> Oct 4 15:55:50 localhost kernel: [] reiserfs_readpages=
+0x18/0x20
> Oct 4 15:55:50 localhost kernel: [] __do_page_cache_re=
adahead+0x20d/0x2c0
> Oct 4 15:55:50 localhost kernel: [] ? __do_page_cache_=
readahead+0xb5/0x2c0
> Oct 4 15:55:50 localhost kernel: [] ? fbcon_decor_curs=
or+0x150/0x1e0
> Oct 4 15:55:50 localhost kernel: [] ra_submit+0x1c/0x20
> Oct 4 15:55:50 localhost kernel: [] ondemand_readahead=
+0x106/0x2b0
> Oct 4 15:55:50 localhost kernel: [] page_cache_sync_re=
adahead+0x2c/0x40
> Oct 4 15:55:50 localhost kernel: [] generic_file_aio_r=
ead+0x428/0x770
> Oct 4 15:55:50 localhost kernel: [] do_sync_read+0xd2/=
0x110
> Oct 4 15:55:50 localhost kernel: [] ? security_file_pe=
rmission+0x8c/0xa0
> Oct 4 15:55:50 localhost kernel: [] vfs_read+0xc3/0x170
> Oct 4 15:55:50 localhost kernel: [] sys_read+0x4c/0x90
> Oct 4 15:55:50 localhost kernel: [] system_call_fastpa=
th+0x16/0x1b
> Oct 4 15:55:50 localhost kernel: BUG: spinlock lockup on CPU#3, flush-9:=
127/2391, ffff880419c37200
> Oct 4 15:55:50 localhost kernel: Pid: 2391, comm: flush-9:127 Tainted: G=
W 3.0.4-gentoo-r1 #7
> Oct 4 15:55:50 localhost kernel: Call Trace:
> Oct 4 15:55:50 localhost kernel: [] do_raw_spin_lock+0=
x156/0x170
> Oct 4 15:55:50 localhost kernel: [] _raw_spin_lock_irq=
+0x44/0x50
> Oct 4 15:55:50 localhost kernel: [] ? get_active_strip=
e+0x35/0x6f0
> Oct 4 15:55:50 localhost kernel: [] get_active_stripe+=
0x35/0x6f0
> Oct 4 15:55:50 localhost kernel: [] ? mark_held_locks+=
0x72/0xa0
> Oct 4 15:55:50 localhost kernel: [] ? get_parent_ip+0x=
11/0x50
> Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_coun=
t+0x95/0xd0
> Oct 4 15:55:50 localhost kernel: [] ? _raw_spin_unlock=
_irqrestore+0x3d/0x70
> Oct 4 15:55:50 localhost kernel: [] ? prepare_to_wait+=
0x5b/0x90
> Oct 4 15:55:50 localhost kernel: [] make_request+0x1a8=
/0x720
> Oct 4 15:55:50 localhost kernel: [] ? wake_up_bit+0x40=
/0x40
> Oct 4 15:55:50 localhost kernel: [] md_make_request+0x=
16e/0x2f0
> Oct 4 15:55:50 localhost kernel: [] ? md_make_request+=
0x58/0x2f0
> Oct 4 15:55:50 localhost kernel: [] ? kmem_cache_alloc=
+0x33/0xc0
> Oct 4 15:55:50 localhost kernel: [] generic_make_reque=
st+0x14c/0x2f0
> Oct 4 15:55:50 localhost kernel: [] submit_bio+0x61/0x=
d0
> Oct 4 15:55:50 localhost kernel: [] submit_bh+0xe6/0x1=
20
> Oct 4 15:55:50 localhost kernel: [] __block_write_full=
_page+0x1f7/0x370
> Oct 4 15:55:50 localhost kernel: [] ? block_read_full_=
page+0x3b0/0x3b0
> Oct 4 15:55:50 localhost kernel: [] ? I_BDEV+0x10/0x10
> Oct 4 15:55:50 localhost kernel: [] ? I_BDEV+0x10/0x10
> Oct 4 15:55:50 localhost kernel: [] block_write_full_p=
age_endio+0xee/0x130
> Oct 4 15:55:50 localhost kernel: [] ? mark_held_locks+=
0x72/0xa0
> Oct 4 15:55:50 localhost kernel: [] block_write_full_p=
age+0x10/0x20
> Oct 4 15:55:50 localhost kernel: [] blkdev_writepage+0=
x13/0x20
> Oct 4 15:55:50 localhost kernel: [] __writepage+0x15/0=
x50
> Oct 4 15:55:50 localhost kernel: [] write_cache_pages+=
0x1f1/0x420
> Oct 4 15:55:50 localhost kernel: [] ? set_page_dirty+0=
x70/0x70
> Oct 4 15:55:50 localhost kernel: [] generic_writepages=
+0x48/0x60
> Oct 4 15:55:50 localhost kernel: [] do_writepages+0x1f=
/0x40
> Oct 4 15:55:50 localhost kernel: [] writeback_single_i=
node+0xf9/0x260
> Oct 4 15:55:50 localhost kernel: [] writeback_sb_inode=
s+0xe8/0x1c0
> Oct 4 15:55:50 localhost kernel: [] writeback_inodes_w=
b+0x83/0x180
> Oct 4 15:55:50 localhost kernel: [] wb_writeback+0x2bb=
/0x330
> Oct 4 15:55:50 localhost kernel: [] ? sub_preempt_coun=
t+0x95/0xd0
> Oct 4 15:55:50 localhost kernel: [] wb_do_writeback+0x=
240/0x250
> Oct 4 15:55:50 localhost kernel: [] bdi_writeback_thre=
ad+0x92/0x180
> Oct 4 15:55:50 localhost kernel: [] ? wb_do_writeback+=
0x250/0x250
> Oct 4 15:55:50 localhost kernel: [] kthread+0x96/0xa0
> Oct 4 15:55:50 localhost kernel: [] kernel_thread_help=
er+0x4/0x10
> Oct 4 15:55:50 localhost kernel: [] ? finish_task_swit=
ch+0x80/0x110
> Oct 4 15:55:50 localhost kernel: [] ? retint_restore_a=
rgs+0xe/0xe
> Oct 4 15:55:50 localhost kernel: [] ? __init_kthread_w=
orker+0x70/0x70
> Oct 4 15:55:50 localhost kernel: [] ? gs_change+0xb/0xb
>=20
> Why date a failure to report?What next?
> Thanks.
>=20
> ---
> ParamonovValery.


--Sig_/hNgepwMnoJReQeP6W6us2Op
Content-Type: application/pgp-signature; name=signature.asc
Content-Disposition: attachment; filename=signature.asc

-----BEGIN PGP SIGNATURE-----
Version: GnuPG v2.0.18 (GNU/Linux)

iQIVAwUBTo5SYjnsnt1WYoG5AQJzEg//U+whEzbYI3IK2l1Zc13dfY32LHXF ertr
NBdpgW1I0kd4XblaJVVAG3XnpmXU1oxdL1SAUxrSO095YNOiTy9DRqipgUbI kC6g
G1SmMtzowXkLwnTnww0eAGxOAFe0lyEgcEOgOZR8SQMAILSuOW/0yQ7nf0V6 ehXV
L4iWVh5VJceQqtj6xR2WrihTiGVLIao9/Ud4GTDW6905kzoo8DzZKuvnn4BY fIH8
dDhAPI0Li4ly1nSSoZp8aPaVsVJhZ3oZt4p/VfhqtL822+wzOR4jbzfl1ZSR +Vbo
yaSMrhLfjlEo1224wAF3/tRXKopwRtIJcvOwdg8vCugCtcgTKfxX4MJdEKye 9TkT
1pYR4dQacwlI+wzIiAD3s1waXXuQ5K6F2NpkrxpxntUjaU9DINxGd83pp1S1 BZJg
PpvRAoHJz6TiAcuZl3lZMoj9JumWF9sHhZYdUQesFJevhWYqAFcLuD8tHSEP 9wHq
1ezQ3nosG2SgfqcwdvY5154I61ffjD1IptFDvEBdUrBfvI9nVK7vr/QG9G+u +F8I
/D0RMvCuGpQVQqwn/GfcOYtKuHkdP8nxtaYeki2r4n1LDWPCK6JzYXMK+7C/ SZcK
YcAAd1ahB0PLuA0Mtc61O7owSyrimW8BoIW4qqJ+zDnRLQjNJcN7fMqJDl0X eSSH
xXUWzRwuujA=
=Y9i4
-----END PGP SIGNATURE-----

--Sig_/hNgepwMnoJReQeP6W6us2Op--