I'm running into a significant slowdown in Btrfs (> 10x slower than
normal) that appears to be due to some issue between how Btrfs is
allocating memory, and how the kernel is expecting Btrfs to allocate
memory.
The problem does seem to be somewhat hardware specific. I can
reproduce on two of my computers (an older AMD Athlon(tm) XP 2600+
with PATA, and a newer ACER Aspire netbook with an Atom CPU). My
Core2Duo computer with SATA seems unaffected by this slowdown.
I've replicated this on 2.6.38, 2.6.39, and 3.0 kernels. The
following information was all obtained running on a 3.0 kernel merged
with the latest 'for-linus' branch of Chris' git repo. I've also
tested on ext4 (no slow down encountered) to make sure the issue
wasn't completely unrelated to Btrfs.
The steps to reproduce are as follows:
Prerequisite: Have a btrfs partition with a copy of a linux kernel
git repository stored.
(1) Boot with 768 MB RAM (using 'mem=768M' in the grub command line).
(2) From a second machine, run a git clone of of the kernel git
repository (such as 'git clone
ssh://<user>@<address>/path/to/linux-git-repo').
The clone process slows down when it reaches the 'remote: Compressing
objects:' step. Looking at the Alt-SysRq-W output and Latencytop
output (see attached), I get a steady stream of memory page faults,
and other memory issues.
The git clone is definitely causing memory pressure when booted with
only 768MB of RAM. However, I still see plenty of cached RAM
available, and there is little or no activity on my swap partition.
The dmesg output is otherwise silent except for the Alt-SysRq-W
output. No OOM errors.
A typical 'top' snapshot during the affected period looks like this:
top - 08:53:08 up 32 min, 3 users, load average: 1.06, 1.01, 0.84
Tasks: 104 total, 1 running, 103 sleeping, 0 stopped, 0 zombie
Cpu(s): 2.3%us, 12.3%sy, 0.0%ni, 0.0%id, 85.1%wa, 0.0%hi, 0.3%si, 0.0%st
Mem: 768452k total, 760248k used, 8204k free, 4396k buffers
Swap: 1004056k total, 13824k used, 990232k free, 352596k cached
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2876 root 20 0 0 0 0 S 11.0 0.0 1:26.62
btrfs-endio-1
3117 dontpani 20 0 720m 386m 52m D 4.0 51.5 2:38.78 git
526 root 20 0 0 0 0 S 0.3 0.0 0:06.42 kswapd0
2576 root 20 0 0 0 0 S 0.3 0.0 0:44.09
btrfs-endio-0
1 root 20 0 1844 568 540 S 0.0 0.1 0:00.32 init
2 root 20 0 0 0 0 S 0.0 0.0 0:00.00 kthreadd
3 root 20 0 0 0 0 S 0.0 0.0 0:00.00
ksoftirqd/0
5 root 20 0 0 0 0 S 0.0 0.0 0:00.01
kworker/u:0
6 root -2 0 0 0 0 S 0.0 0.0 0:04.17
rcu_kthread
7 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 cpuset
8 root 0 -20 0 0 0 S 0.0 0.0 0:00.00 khelper
So, while I may be truly running out of RAM, the kernel doesn't seem
to be handling issue normally (i.e., pushing more off to the Swap or
giving OOM errors).
Let me know if you have some feedback on how to track this issue down.
=============== Mon Aug 1 14:24:05 2011
Globals: Cause Maximum Percentage
Page fault 189.6 msec 100.0 %
Process details:
Process kworker/0:1 (395) Total: 27.6 msec
. 4.9 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kswapd0 (526) Total: 11.5 msec
kswapd() kernel thread 3.6 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 878.4 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 1.1 msec
[worker_loop] 1.1 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 1117.1 msec
Page fault 189.6 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
=============== Mon Aug 1 14:24:15 2011
Globals: Cause Maximum Percentage
Page fault 388.9 msec 98.0 %
Creating block layer request 74.6 msec 0.8 %
Reading from file 74.1 msec 0.8 %
[sleep_on_page] 37.9 msec 0.4 %
Waiting for event (poll) 1.8 msec 0.0 %
Waiting for event (select) 1.7 msec 0.0 %
Process details:
Process sync_supers (259) Total: 0.5 msec
Waiting for buffer IO to complete 0.3 msec 100.0 %
sleep_on_buffer __wait_on_buffer flush_commit_list
do_journal_end.clone.32 journal_end_sync reiserfs_sync_fs
reiserfs_write_super sync_supers bdi_sync_supers kthread
kernel_thread_helper
Process kworker/0:1 (395) Total: 0.2 msec
. 0.2 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kswapd0 (526) Total: 33.8 msec
kswapd() kernel thread 4.3 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4667.5 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process sshd (2765) Total: 1.7 msec
Waiting for event (select) 1.7 msec 100.0 %
poll_schedule_timeout do_select core_sys_select sys_select
sysenter_do_call
Process git-upload-pack (2766) Total: 1.8 msec
Waiting for event (poll) 1.8 msec 100.0 %
poll_schedule_timeout do_sys_poll sys_poll sysenter_do_call
Process btrfs-endio-1 (2768) Total: 10.2 msec
[worker_loop] 1.1 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9399.2 msec
Page fault 388.9 msec 98.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 74.6 msec 0.8 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages __do_page_cache_readahead
Reading from file 74.1 msec 0.8 %
sleep_on_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read sysenter_do_call
[sleep_on_page] 37.9 msec 0.4 %
sleep_on_page wait_on_page_bit read_extent_buffer_pages
btree_read_extent_buffer_pages.clone.68 read_tree_block
read_block_for_search.clone.40 btrfs_search_slot
btrfs_lookup_file_extent btrfs_get_extent
__extent_read_full_page extent_readpages btrfs_readpages
=============== Mon Aug 1 14:24:25 2011
Globals: Cause Maximum Percentage
Page fault 338.2 msec 100.0 %
Creating block layer request 0.9 msec 0.0 %
Process details:
Process kswapd0 (526) Total: 25.1 msec
kswapd() kernel thread 2.6 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4946.4 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 10.0 msec
[worker_loop] 1.2 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9202.4 msec
Page fault 338.2 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 0.9 msec 0.0 %
mempool_alloc get_request get_request_wait __make_request
generic_make_request submit_bio btrfs_map_bio
btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page extent_readpages
=============== Mon Aug 1 14:24:35 2011
Globals: Cause Maximum Percentage
Page fault 413.3 msec 99.8 %
Synchronous buffer read 14.4 msec 0.2 %
Process details:
Process sync_supers (259) Total: 0.8 msec
Waiting for buffer IO to complete 0.4 msec 100.0 %
sleep_on_buffer __wait_on_buffer
write_ordered_buffers.clone.29 flush_commit_list
do_journal_end.clone.32 journal_end_sync reiserfs_sync_fs
reiserfs_write_super sync_supers bdi_sync_supers kthread
kernel_thread_helper
Process kworker/0:1 (395) Total: 1.0 msec
. 0.5 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kswapd0 (526) Total: 56.2 msec
kswapd() kernel thread 2.8 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4947.7 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 27.1 msec
[worker_loop] 2.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9439.9 msec
Page fault 413.3 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Process latencytop (2844) Total: 14.4 msec
Synchronous buffer read 14.4 msec 100.0 %
sleep_on_buffer __wait_on_buffer __bread
reiserfs_read_bitmap_block scan_bitmap_block.clone.11
reiserfs_allocate_blocknrs _allocate_block reiserfs_get_block
__block_write_begin reiserfs_write_begin
generic_file_buffered_write __generic_file_aio_write
=============== Mon Aug 1 14:24:45 2011
Globals: Cause Maximum Percentage
Page fault 411.1 msec 100.0 %
Process details:
Process kswapd0 (526) Total: 52.7 msec
kswapd() kernel thread 4.7 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4964.7 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process ntpd (2608) Total: 32.9 msec
Page fault 17.5 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Process btrfs-endio-1 (2768) Total: 16.5 msec
[worker_loop] 1.2 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9152.3 msec
Page fault 411.1 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
=============== Mon Aug 1 14:24:55 2011
Globals: Cause Maximum Percentage
Page fault 317.7 msec 99.3 %
Creating block layer request 60.9 msec 0.7 %
Process details:
Process kswapd0 (526) Total: 52.5 msec
kswapd() kernel thread 4.0 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 5134.5 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 25.9 msec
[worker_loop] 1.5 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9130.0 msec
Page fault 317.7 msec 99.3 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 60.9 msec 0.7 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages __do_page_cache_readahead
=============== Mon Aug 1 14:25:05 2011
Globals: Cause Maximum Percentage
Page fault 334.6 msec 87.9 %
Waiting for buffer IO to complete 85.9 msec 0.7 %
Creating block layer request 78.4 msec 1.2 %
synchronous write 26.2 msec 0.3 %
Reading from file 11.1 msec 0.1 %
Waiting for data on unix socket 4.8 msec 7.2 %
Reading from a pipe 3.9 msec 0.1 %
Userspace lock contention 2.9 msec 0.0 %
Waiting for a process to die 2.0 msec 0.0 %
Process details:
Process sync_supers (259) Total: 4.0 msec
Waiting for buffer IO to complete 1.4 msec 100.0 %
sleep_on_buffer __wait_on_buffer
write_ordered_buffers.clone.29 flush_commit_list
do_journal_end.clone.32 journal_end_sync reiserfs_sync_fs
reiserfs_write_super sync_supers bdi_sync_supers kthread
kernel_thread_helper
Process kworker/0:1 (395) Total: 56.4 msec
. 4.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process kswapd0 (526) Total: 36.6 msec
kswapd() kernel thread 3.2 msec 100.0 %
kswapd kthread kernel_thread_helper
Process kworker/0:3 (891) Total: 68.1 msec
. 4.8 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process syslog-ng (2398) Total: 173.7 msec
Page fault 162.2 msec 93.4 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
synchronous write 11.5 msec 6.6 %
sleep_on_buffer __wait_on_buffer __block_write_begin
reiserfs_write_begin generic_file_buffered_write
__generic_file_aio_write generic_file_aio_write do_sync_write
reiserfs_file_write vfs_write sys_write sysenter_do_call
Process btrfs-endio-0 (2567) Total: 5092.7 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process mysqld (2626) Total: 81.9 msec
Page fault 12.3 msec 97.5 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Userspace lock contention 2.0 msec 2.5 %
futex_wait_queue_me futex_wait do_futex sys_futex sysenter_do_call
Process btrfs-endio-1 (2768) Total: 26.9 msec
[worker_loop] 3.2 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9188.0 msec
Page fault 334.6 msec 98.4 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 78.4 msec 1.6 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_compressed_read
btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages
=============== Mon Aug 1 14:25:16 2011
Globals: Cause Maximum Percentage
Page fault 315.4 msec 96.8 %
Reading from file 152.5 msec 2.6 %
Creating block layer request 60.4 msec 0.7 %
Process details:
Process kswapd0 (526) Total: 47.4 msec
kswapd() kernel thread 5.0 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4983.0 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 17.7 msec
[worker_loop] 2.3 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9219.7 msec
Page fault 315.4 msec 96.8 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Reading from file 152.5 msec 2.6 %
sleep_on_page_killable __lock_page_killable
generic_file_aio_read do_sync_read vfs_read sys_read sysenter_do_call
Creating block layer request 60.4 msec 0.7 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages __do_page_cache_readahead
=============== Mon Aug 1 14:25:26 2011
Globals: Cause Maximum Percentage
Page fault 349.8 msec 97.3 %
Creating block layer request 89.8 msec 2.3 %
[mempool_alloc] 33.1 msec 0.4 %
Process details:
Process sync_supers (259) Total: 0.5 msec
Waiting for buffer IO to complete 0.2 msec 100.0 %
sleep_on_buffer __wait_on_buffer
write_ordered_buffers.clone.29 flush_commit_list
do_journal_end.clone.32 journal_end_sync reiserfs_sync_fs
reiserfs_write_super sync_supers bdi_sync_supers kthread
kernel_thread_helper
Process kswapd0 (526) Total: 140.0 msec
kswapd() kernel thread 97.3 msec 100.0 %
kswapd kthread kernel_thread_helper
Process kworker/0:3 (891) Total: 4.2 msec
. 3.4 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4890.9 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 29.5 msec
[worker_loop] 1.7 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9350.9 msec
Page fault 349.8 msec 97.3 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 89.8 msec 2.3 %
mempool_alloc get_request get_request_wait __make_request
generic_make_request submit_bio btrfs_map_bio
btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page extent_readpages
[mempool_alloc] 33.1 msec 0.4 %
mempool_alloc bvec_alloc_bs bio_alloc_bioset bio_alloc
btrfs_bio_alloc compressed_bio_alloc.clone.14
btrfs_submit_compressed_read btrfs_submit_bio_hook
submit_one_bio submit_extent_page.clone.27
__extent_read_full_page extent_readpages
=============== Mon Aug 1 14:25:36 2011
Globals: Cause Maximum Percentage
Page fault 329.7 msec 96.4 %
Creating block layer request 120.6 msec 3.6 %
Process details:
Process kswapd0 (526) Total: 35.5 msec
kswapd() kernel thread 3.5 msec 100.0 %
kswapd kthread kernel_thread_helper
Process kworker/0:3 (891) Total: 0.6 msec
. 0.6 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4714.3 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 9.6 msec
[worker_loop] 1.7 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9280.7 msec
Page fault 329.7 msec 96.4 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 120.6 msec 3.6 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages __do_page_cache_readahead
Process latencytop (2844) Total: 1.0 msec
Page fault 0.6 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry handle_pte_fault handle_mm_fault
do_page_fault error_code
=============== Mon Aug 1 14:25:46 2011
Globals: Cause Maximum Percentage
Page fault 522.1 msec 96.4 %
Creating block layer request 115.4 msec 3.6 %
Process details:
Process kswapd0 (526) Total: 38.2 msec
kswapd() kernel thread 2.0 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4884.8 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 31.3 msec
[worker_loop] 1.3 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9232.9 msec
Page fault 522.1 msec 96.4 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 115.4 msec 3.6 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_compressed_read
btrfs_submit_bio_hook submit_one_bio
submit_extent_page.clone.27 __extent_read_full_page
extent_readpages btrfs_readpages
=============== Mon Aug 1 14:25:56 2011
Globals: Cause Maximum Percentage
Page fault 373.0 msec 100.0 %
Waiting for event (select) 0.4 msec 0.0 %
Process details:
Process sync_supers (259) Total: 0.6 msec
Waiting for buffer IO to complete 0.2 msec 100.0 %
sleep_on_buffer __wait_on_buffer
write_ordered_buffers.clone.29 flush_commit_list
do_journal_end.clone.32 journal_end_sync reiserfs_sync_fs
reiserfs_write_super sync_supers bdi_sync_supers kthread
kernel_thread_helper
Process kswapd0 (526) Total: 42.8 msec
kswapd() kernel thread 3.9 msec 100.0 %
kswapd kthread kernel_thread_helper
Process kworker/0:3 (891) Total: 2.0 msec
. 1.3 msec 100.0 %
worker_thread kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4997.7 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process ntpd (2608) Total: 0.4 msec
Waiting for event (select) 0.4 msec 100.0 %
poll_schedule_timeout do_select core_sys_select sys_select
sysenter_do_call
Process btrfs-endio-1 (2768) Total: 15.2 msec
[worker_loop] 1.2 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9218.2 msec
Page fault 373.0 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
=============== Mon Aug 1 14:26:06 2011
Globals: Cause Maximum Percentage
Page fault 344.3 msec 99.2 %
Creating block layer request 73.4 msec 0.8 %
Process details:
Process kswapd0 (526) Total: 53.2 msec
kswapd() kernel thread 2.3 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 5131.4 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 27.9 msec
[worker_loop] 1.3 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9203.7 msec
Page fault 344.3 msec 99.2 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
Creating block layer request 73.4 msec 0.8 %
get_request_wait __make_request generic_make_request
submit_bio btrfs_map_bio btrfs_submit_compressed_read
btrfs_submit_bio_hook submit_one_bio extent_readpages
btrfs_readpages __do_page_cache_readahead ra_submit
=============== Mon Aug 1 14:26:16 2011
Globals: Cause Maximum Percentage
Page fault 309.7 msec 100.0 %
Process details:
Process kswapd0 (526) Total: 33.6 msec
kswapd() kernel thread 4.7 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4955.9 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 8.0 msec
[worker_loop] 1.3 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 8880.4 msec
Page fault 309.7 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
=============== Mon Aug 1 14:26:26 2011
Globals: Cause Maximum Percentage
Page fault 376.8 msec 100.0 %
Process details:
Process kswapd0 (526) Total: 39.3 msec
kswapd() kernel thread 2.0 msec 100.0 %
kswapd kthread kernel_thread_helper
Process btrfs-endio-0 (2567) Total: 4944.7 msec
[worker_loop] 5.0 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process btrfs-endio-1 (2768) Total: 23.8 msec
[worker_loop] 1.2 msec 100.0 %
worker_loop kthread kernel_thread_helper
Process git (2769) Total: 9058.2 msec
Page fault 376.8 msec 100.0 %
sleep_on_page_killable wait_on_page_bit_killable
__lock_page_or_retry filemap_fault __do_fault handle_pte_fault
handle_mm_fault do_page_fault error_code
[ 1066.031535] SysRq : Show Blocked State
[ 1066.031682] task PC stack pid father
[ 1066.031712] git D 00000000 0 2877 2874 0x00000000
[ 1066.031718] ec50bdc8 00000086 00e4cd0a 00000000 eee4c8b4 eec7a1c8 eee4c824 eedc2530
[ 1066.031724] ec50bd78 ec50bdc8 ee933d40 31772fc6 000000f8 ee933d40 00000000 00000006
[ 1066.031730] 7d9acaea 000001f0 ee93f16c ee93f16c ec50bdc0 c1055557 3ab3262f 00000000
[ 1066.031735] Call Trace:
[ 1066.031747] [<c1055557>] ? ktime_get_ts+0xe7/0x110
[ 1066.031754] [<c170bf33>] io_schedule+0x63/0xa0
[ 1066.031760] [<c10a9d9d>] sleep_on_page_killable+0xd/0x40
[ 1066.031764] [<c170c5fd>] __wait_on_bit+0x4d/0x70
[ 1066.031768] [<c10a9d90>] ? sleep_on_page+0x20/0x20
[ 1066.031772] [<c10abcb6>] wait_on_page_bit_killable+0x86/0xa0
[ 1066.031781] [<c104c590>] ? autoremove_wake_function+0x50/0x50
[ 1066.031785] [<c10abd62>] __lock_page_or_retry+0x92/0xb0
[ 1066.031789] [<c10abf04>] filemap_fault+0x184/0x350
[ 1066.031794] [<c10c2de1>] __do_fault+0x41/0x3e0
[ 1066.031798] [<c10c5065>] handle_pte_fault+0x85/0x5c0
[ 1066.031802] [<c10c5627>] handle_mm_fault+0x87/0xd0
[ 1066.031808] [<c170ff20>] ? spurious_fault+0xd0/0xd0
[ 1066.031812] [<c1710064>] do_page_fault+0x144/0x430
[ 1066.031819] [<c13c5a5a>] ? radix_tree_lookup+0xa/0x10
[ 1066.031826] [<c1037057>] ? irq_exit+0x37/0x90
[ 1066.031830] [<c1713db8>] ? do_IRQ+0x48/0x94
[ 1066.031835] [<c10c92d2>] ? sys_mmap_pgoff+0x122/0x1d0
[ 1066.031839] [<c170ff20>] ? spurious_fault+0xd0/0xd0
[ 1066.031843] [<c170dac4>] error_code+0x58/0x60
[ 1066.031847] [<c170ff20>] ? spurious_fault+0xd0/0xd0
[ 1066.031852] Sched Debug Version: v0.10, 3.0.0-git-local-v1+ #4
[ 1066.031856] ktime : 1066031.850886
[ 1066.031859] sched_clk : 1066115.409241
[ 1066.031862] cpu_clk : 1066031.850954
[ 1066.031865] jiffies : 766031
[ 1066.031867] sched_clock_stable : 0
[ 1066.031869]
[ 1066.031870] sysctl_sched
[ 1066.031872] .sysctl_sched_latency : 6.000000
[ 1066.031875] .sysctl_sched_min_granularity : 0.750000
[ 1066.031878] .sysctl_sched_wakeup_granularity : 1.000000
[ 1066.031880] .sysctl_sched_child_runs_first : 0
[ 1066.031883] .sysctl_sched_features : 15471
[ 1066.031885] .sysctl_sched_tunable_scaling : 1 (logaritmic)
[ 1066.031889]
[ 1066.031889] cpu#0, 1921.136 MHz
[ 1066.031892] .nr_running : 0
[ 1066.031894] .load : 0
[ 1066.031896] .nr_switches : 717095
[ 1066.031898] .nr_load_updates : 255524
[ 1066.031900] .nr_uninterruptible : 1
[ 1066.031903] .next_balance : 0.000000
[ 1066.031905] .curr->pid : 0
[ 1066.031908] .clock : 1066030.827694
[ 1066.031910] .cpu_load[0] : 1024
[ 1066.031912] .cpu_load[1] : 900
[ 1066.031915] .cpu_load[2] : 627
[ 1066.031917] .cpu_load[3] : 393
[ 1066.031919] .cpu_load[4] : 263
[ 1066.031921] .yld_count : 2
[ 1066.031923] .sched_switch : 0
[ 1066.031925] .sched_count : 866330
[ 1066.031928] .sched_goidle : 167872
[ 1066.031930] .ttwu_count : 375079
[ 1066.031932] .ttwu_local : 0
[ 1066.031936]
[ 1066.031936] cfs_rq[0]:/
[ 1066.031939] .exec_clock : 253617.234849
[ 1066.031942] .MIN_vruntime : 0.000001
[ 1066.031945] .min_vruntime : 227564.194600
[ 1066.031948] .max_vruntime : 0.000001
[ 1066.031950] .spread : 0.000000
[ 1066.031953] .spread0 : 0.000000
[ 1066.031955] .nr_spread_over : 2852
[ 1066.031957] .nr_running : 0
[ 1066.031959] .load : 0
[ 1066.031962]
[ 1066.031963] rt_rq[0]:
[ 1066.031965] .rt_nr_running : 0
[ 1066.031967] .rt_throttled : 0
[ 1066.031969] .rt_time : 0.000000
[ 1066.031972] .rt_runtime : 950.000000
[ 1066.031975]
[ 1066.031976] runnable tasks:
[ 1066.031977] task PID tree-key switches prio exec-runtime sum-exec sum-sleep
[ 1066.031979] ----------------------------------------------------------------------------------------------------------
