ext4, jbd2: task blocked for more than 120 seconds.

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index]

 



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@xxxxxxxxx
--
To unsubscribe from this list: send the line "unsubscribe linux-ext4" in
the body of a message to majordomo@xxxxxxxxxxxxxxx
More majordomo info at  http://vger.kernel.org/majordomo-info.html




[Index of Archives]     [Reiser Filesystem Development]     [Ceph FS]     [Kernel Newbies]     [Security]     [Netfilter]     [Bugtraq]     [Linux FS]     [Yosemite National Park]     [MIPS Linux]     [ARM Linux]     [Linux Security]     [Linux RAID]     [Samba]     [Device Mapper]     [Linux Media]

  Powered by Linux