| lists.openwall.net | lists / announce owl-users owl-dev john-users john-dev passwdqc-users yescrypt popa3d-users / oss-security kernel-hardening musl sabotage tlsify passwords / crypt-dev xvendor / Bugtraq Full-Disclosure linux-kernel linux-netdev linux-ext4 linux-hardening linux-cve-announce PHC | |
|
Open Source and information security mailing list archives
| ||
|
Message-ID: <CAAW1UO_+_z8zyRhX-HZKWHsxiZ8fE54bZvxU_uuXTmMQ3=+qSA@mail.gmail.com>
Date: Mon, 22 Apr 2013 09:40:03 +0400
From: Azat Khuzhin <dohardgopro@...il.com>
To: linux-ext4@...r.kernel.org
Subject: Re: ext4, jbd2: task blocked for more than 120 seconds.
Here is more that I tried to do:
$ umount /dev/sdb5 # finished successfully
$ debugfs
open_filesys /dev/sdb5 # finished successfully
# Then I copy some files that I need at that moment to another partition
# After I try to mount it
$ mount /dev/sdb5 # didn't finished
root:/sys# cat /proc/$(pgrep mount)/status | grep State
State: D (disk sleep)
On Sat, Apr 20, 2013 at 8:05 PM, Azat Khuzhin <dohardgopro@...il.com> wrote:
> Today I have "blocked for more than 120 seconds" in dmesg, while doing
> next things:
>
> - Run ktorrent
> - Download torrent, and don't have enough space to save
> - mv of 84 GiB folder into another parititon (not waiting for the end)
> - Continue downloading with ktorrent
> - When there is only 4.0K available on partition (where ktorrent
> saves), all jobs hangs
> - ktorrent
> - mv, that not finished
> - mplayer, that try to get next file (seems that current one was in
> cache, about 130 MiB in size)
>
> And after this load avg was equal to 8.
>
> I've try to investigate further, see into some old patches, blame, but
> I don't have any ideas.
> So here is some more info about it:
>
> # Kernel version:
>
> $ uname -a
> Linux home-spb 3.8.0custom.x86-64.1.8-10206-gb0af9cd-dirty #1 SMP Sun
> Mar 3 20:39:58 MSK 2013 x86_64 GNU/Linux
> $ grep sdb5 /proc/mounts
> /dev/sdb5 /mnt/docs ext4 rw,relatime,data=ordered 0 0
>
> $ iostat 2 /dev/sdb
> Linux 3.8.0custom.x86-64.1.8-10206-gb0af9cd-dirty (home-spb)
> 04/20/2013 _x86_64_ (4 CPU)
>
> avg-cpu: %user %nice %system %iowait %steal %idle
> 3.31 0.00 0.59 0.56 0.00 95.54
>
> Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
> sdb 0.76 34.68 32.07 29794122 27548981
>
> avg-cpu: %user %nice %system %iowait %steal %idle
> 2.39 0.00 0.38 0.00 0.00 97.23
>
> Device: tps kB_read/s kB_wrtn/s kB_read kB_wrtn
> sdb 0.00 0.00 0.00 0 0
>
> # dmesg snippets
>
> [836402.486062] INFO: task flush-8:16:24991 blocked for more than 120 seconds.
> [836402.486738] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [836402.488080] flush-8:16 D ffff88022ea93a40 0 24991 2 0x00000000
> [836402.489419] ffff8801cb341c40 0000000000000046 ffff88020a20b9b8
> ffff8802258fc6a0
> [836402.490747] 0000000000013a40 ffff88020a20bfd8 ffff88020a20bfd8
> ffff8801cb341c40
> [836402.492091] 0000000000000092 ffff8801cb341c40 ffff8801fe8d2980
> 0000000000000001
> [836402.493457] Call Trace:
> [836402.494133] [<ffffffff813a9701>] ? rwsem_down_failed_common+0x1bd/0x1f6
> [836402.494810] [<ffffffff810c828b>] ? release_pages+0x159/0x168
> [836402.495485] [<ffffffff811fcea3>] ? call_rwsem_down_write_failed+0x13/0x20
> [836402.496163] [<ffffffff813a85c4>] ? down_write+0x25/0x27
> [836402.496838] [<ffffffff8115e264>] ? ext4_map_blocks+0x1d0/0x30e
> [836402.497514] [<ffffffff8116142d>] ? mpage_da_map_and_submit+0x8a/0x314
> [836402.498185] [<ffffffff81161cc7>] ? ext4_da_writepages+0x2ab/0x44e
> [836402.498868] [<ffffffff811e1f5e>] ? __blk_run_queue_uncond+0x1e/0x26
> [836402.499544] [<ffffffff811e1fd0>] ? queue_unplugged+0x59/0x7d
> [836402.500297] [<ffffffff8111d7a0>] ? __writeback_single_inode+0x4b/0x1d6
> [836402.501019] [<ffffffff8111df91>] ? writeback_sb_inodes+0x1dd/0x30c
> [836402.501763] [<ffffffff8111e129>] ? __writeback_inodes_wb+0x69/0xab
> [836402.502503] [<ffffffff8111e2a2>] ? wb_writeback+0x137/0x28c
> [836402.503207] [<ffffffff8111ecff>] ? wb_do_writeback+0x146/0x1bb
> [836402.503922] [<ffffffff81046fbe>] ? del_timer_sync+0x27/0x44
> [836402.504636] [<ffffffff8111ed74>] ? wb_do_writeback+0x1bb/0x1bb
> [836402.505345] [<ffffffff8111ee1c>] ? bdi_writeback_thread+0xa8/0x1db
> [836402.506031] [<ffffffff8111ed74>] ? wb_do_writeback+0x1bb/0x1bb
> [836402.506739] [<ffffffff8111ed74>] ? wb_do_writeback+0x1bb/0x1bb
> [836402.507413] [<ffffffff810551b0>] ? kthread+0x81/0x89
> [836402.508089] [<ffffffff8105512f>] ? __kthread_parkme+0x5c/0x5c
> [836402.508795] [<ffffffff813afafc>] ? ret_from_fork+0x7c/0xb0
> [836402.509467] [<ffffffff8105512f>] ? __kthread_parkme+0x5c/0x5c
> [836402.510157] INFO: task mv:31543 blocked for more than 120 seconds.
> [836402.510848] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [836402.512206] mv D ffff88022ea13a40 0 31543 30551 0x00000000
> [836402.513550] ffff880224603170 0000000000000086 0000000000000000
> ffffffff81613400
> [836402.514900] 0000000000013a40 ffff880050b61fd8 ffff880050b61fd8
> ffff880224603170
> [836402.516237] 0000000000000246 ffff880225358800 0000000000000000
> ffff880225358868
> [836402.517598] Call Trace:
> [836402.518266] [<ffffffff811973f8>] ? start_this_handle+0x2d0/0x46b
> [836402.518951] [<ffffffff8105e78b>] ? should_resched+0x5/0x23
> [836402.519630] [<ffffffff810557d1>] ? bit_waitqueue+0x82/0x82
> [836402.520305] [<ffffffff8119772d>] ? jbd2__journal_start+0x94/0x154
> [836402.521027] [<ffffffff8116218f>] ? ext4_dirty_inode+0x1e/0x51
> [836402.521743] [<ffffffff8111d999>] ? __mark_inode_dirty+0x6e/0x1f1
> [836402.522449] [<ffffffff811105f4>] ? update_time+0xa0/0xa9
> [836402.523121] [<ffffffff81110cba>] ? touch_atime+0xe3/0x11c
> [836402.523795] [<ffffffff810bfe8a>] ? generic_file_aio_read+0x55a/0x5b9
> [836402.524476] [<ffffffff810fe062>] ? do_sync_read+0x62/0x9b
> [836402.525156] [<ffffffff810fe663>] ? vfs_read+0x93/0xf5
> [836402.525842] [<ffffffff810fe716>] ? sys_read+0x51/0x80
> [836402.526527] [<ffffffff813afba9>] ? system_call_fastpath+0x16/0x1b
> [836522.558599] INFO: task jbd2/sdb5-8:1794 blocked for more than 120 seconds.
> [836522.559400] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [836522.560999] jbd2/sdb5-8 D ffff88022ea93a40 0 1794 2 0x00000000
> [836522.562591] ffff8802253b3170 0000000000000046 0000000131cd9ccb
> ffff8802258fc6a0
> [836522.564169] 0000000000013a40 ffff880225161fd8 ffff880225161fd8
> ffff8802253b3170
> [836522.565565] 0000000000000246 ffff880225358800 ffff880225161d80
> ffff88008fd7ca70
> [836522.566953] Call Trace:
> [836522.567660] [<ffffffff8119931d>] ?
> jbd2_journal_commit_transaction+0x22f/0x135e
> [836522.569014] [<ffffffff8100d5ff>] ? __switch_to+0x18d/0x3f8
> [836522.569780] [<ffffffff810557d1>] ? bit_waitqueue+0x82/0x82
> [836522.570519] [<ffffffff81046e67>] ? lock_timer_base.isra.37+0x23/0x48
> [836522.571225] [<ffffffff81046f8c>] ? try_to_del_timer_sync+0x4e/0x59
> [836522.571958] [<ffffffff8119f0df>] ? kjournald2+0xb7/0x239
> [836522.572688] [<ffffffff810557d1>] ? bit_waitqueue+0x82/0x82
> [836522.573386] [<ffffffff8119f028>] ? journal_init_common+0x165/0x165
> [836522.574093] [<ffffffff8119f028>] ? journal_init_common+0x165/0x165
> [836522.574772] [<ffffffff810551b0>] ? kthread+0x81/0x89
> [836522.575447] [<ffffffff8105512f>] ? __kthread_parkme+0x5c/0x5c
> [836522.576127] [<ffffffff813afafc>] ? ret_from_fork+0x7c/0xb0
> [836522.576804] [<ffffffff8105512f>] ? __kthread_parkme+0x5c/0x5c
> [836522.577526] INFO: task ktorrent:11063 blocked for more than 120 seconds.
> [836522.578205] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs"
> disables this message.
> [836522.579569] ktorrent D ffff88022eb93a40 0 11063 1 0x00000000
> [836522.580927] ffff8801cb3454c0 0000000000000086 0000000000000292
> ffff8802258fd4c0
> [836522.582274] 0000000000013a40 ffff880050f73fd8 ffff880050f73fd8
> ffff8801cb3454c0
> [836522.583664] 0000000000000246 ffff880225358800 ffff880050f73ab0
> ffff880225358824
> [836522.585006] Call Trace:
> [836522.585694] [<ffffffff8119def0>] ? jbd2_log_wait_commit+0xc3/0x118
> [836522.586371] [<ffffffff810557d1>] ? bit_waitqueue+0x82/0x82
> [836522.587048] [<ffffffff8119ff52>] ?
> jbd2_journal_force_commit_nested+0x63/0x91
> [836522.588388] [<ffffffff8115d729>] ? ext4_da_get_block_prep+0x329/0x485
> [836522.589082] [<ffffffff81122ef3>] ? alloc_buffer_head+0x18/0x5b
> [836522.589775] [<ffffffff81124d80>] ? __block_write_begin+0x125/0x27d
> [836522.590467] [<ffffffff81072724>] ? current_kernel_time+0x9/0x30
> [836522.591144] [<ffffffff8115d400>] ? ext4_num_dirty_pages.isra.44+0x17f/0x17f
> [836522.592502] [<ffffffff810ffe13>] ? __sb_start_write+0xb6/0xe8
> [836522.593195] [<ffffffff810de216>] ? vma_gap_callbacks_propagate+0x13/0x2c
> [836522.593899] [<ffffffff8115d400>] ? ext4_num_dirty_pages.isra.44+0x17f/0x17f
> [836522.595252] [<ffffffff81124f4d>] ? __block_page_mkwrite+0x75/0xb7
> [836522.595932] [<ffffffff81162382>] ? ext4_page_mkwrite+0x8e/0x2a4
> [836522.596614] [<ffffffff810d8e36>] ? __do_fault+0x15b/0x35d
> [836522.597304] [<ffffffff810db20d>] ? handle_pte_fault+0x28b/0x708
> [836522.597981] [<ffffffff81033da9>] ? pte_alloc_one+0x2f/0x39
> [836522.598670] [<ffffffff813aca20>] ? __do_page_fault+0x32d/0x375
> [836522.599346] [<ffffffff810d3498>] ? vm_mmap_pgoff+0x82/0xab
> [836522.600023] [<ffffffff813a9898>] ? _raw_spin_lock_irq+0xb/0x15
> [836522.600700] [<ffffffff8104b8ca>] ? do_sigaction+0xc2/0x167
> [836522.601373] [<ffffffff8105e82c>] ? finish_task_switch+0x83/0xb4
> [836522.602066] [<ffffffff8105e78b>] ? should_resched+0x5/0x23
> [836522.602757] [<ffffffff813a8dd8>] ? _cond_resched+0x6/0x1b
> [836522.603432] [<ffffffff813a9e58>] ? page_fault+0x28/0x30
>
> # Pointers to sources
>
> (gdb) list *(jbd2_log_wait_commit+0xc3)
> 0xffffffff8119def0 is in jbd2_log_wait_commit (fs/jbd2/journal.c:699).
> 694 while (tid_gt(tid, journal->j_commit_sequence)) {
> 695 jbd_debug(1, "JBD2: want %d, j_commit_sequence=%d\n",
> 696 tid, journal->j_commit_sequence);
> 697 wake_up(&journal->j_wait_commit);
> 698 read_unlock(&journal->j_state_lock);
> 699 wait_event(journal->j_wait_done_commit,
> 700 !tid_gt(tid,
> journal->j_commit_sequence));
> 701 read_lock(&journal->j_state_lock);
> 702 }
> 703 read_unlock(&journal->j_state_lock);
> (gdb) list *(jbd2_journal_commit_transaction+0x22f)
> 0xffffffff8119931d is in jbd2_journal_commit_transaction (fs/jbd2/commit.c:457).
> 452 TASK_UNINTERRUPTIBLE);
> 453 if (atomic_read(&commit_transaction->t_updates)) {
> 454 spin_unlock(&commit_transaction->t_handle_lock);
> 455 write_unlock(&journal->j_state_lock);
> 456 schedule();
> 457 write_lock(&journal->j_state_lock);
> 458 spin_lock(&commit_transaction->t_handle_lock);
> 459 }
> 460 finish_wait(&journal->j_wait_updates, &wait);
> 461 }
> (gdb) list *(start_this_handle+0x2d0)
> 0xffffffff811973f8 is in start_this_handle (fs/jbd2/transaction.c:237).
> warning: Source file is more recent than executable.
> 232
> 233 prepare_to_wait(&journal->j_wait_transaction_locked,
> 234 &wait, TASK_UNINTERRUPTIBLE);
> 235 read_unlock(&journal->j_state_lock);
> 236 schedule();
> 237 finish_wait(&journal->j_wait_transaction_locked, &wait);
> 238 goto repeat;
> 239 }
> 240
> 241 /*
> (gdb) l *(ext4_map_blocks+0x1d0)
> 0xffffffff8115e264 is in ext4_map_blocks (fs/ext4/inode.c:609).
> 604 * if the caller is from delayed allocation writeout path
> 605 * we have already reserved fs blocks for allocation
> 606 * let the underlying get_block() function know to
> 607 * avoid double accounting
> 608 */
> 609 if (flags & EXT4_GET_BLOCKS_DELALLOC_RESERVE)
> 610 ext4_set_inode_state(inode,
> EXT4_STATE_DELALLOC_RESERVED);
> 611 /*
> 612 * We need to check for EXT4 here because migrate
> 613 * could have changed the inode type in between
> (gdb) l *(ext4_map_blocks+(0x1d0-8)) # I actually think that instead
> of previous command you want to see at this one.
> 0xffffffff8115e25c is in ext4_map_blocks (fs/ext4/inode.c:601).
> 596 * New blocks allocate and/or writing to uninitialized extent
> 597 * will possibly result in updating i_data, so we take
> 598 * the write lock of i_data_sem, and call get_blocks()
> 599 * with create == 1 flag.
> 600 */
> 601 down_write((&EXT4_I(inode)->i_data_sem));
> 602
> 603 /*
> 604 * if the caller is from delayed allocation writeout path
> 605 * we have already reserved fs blocks for allocation
>
> --
> Respectfully
> Azat Khuzhin
> Primary email a3at.mail@...il.com
--
Respectfully
Azat Khuzhin
Primary email a3at.mail@...il.com
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
the body of a message to majordomo@...r.kernel.org
More majordomo info at http://vger.kernel.org/majordomo-info.html
Powered by blists - more mailing lists