* Re: Performance issue on dual Athlon MP
2002-03-11 9:32 ` Jens Axboe
@ 2002-03-11 20:13 ` Randy.Dunlap
2002-03-14 15:49 ` Scott L. Burson
1 sibling, 0 replies; 10+ messages in thread
From: Randy.Dunlap @ 2002-03-11 20:13 UTC (permalink / raw)
To: Jens Axboe; +Cc: Alan Cox, Scott L. Burson, linux-kernel
[-- Attachment #1: Type: TEXT/PLAIN, Size: 1953 bytes --]
On Mon, 11 Mar 2002, Jens Axboe wrote:
| On Thu, Mar 07 2002, Alan Cox wrote:
| > > BTW, this doesn't seem like a preemption issue, considering that throughput
| > > is very definitely affected as well as latency.
| > >
| > > Anyway, please let me know if there's anything I can do, within my
| > > constraints, to help. (As you can guess, though, I don't have any kernel
| > > debugging experience.)
| >
| > It sounds like the hit you are taking is from highmem and I/O (having to
| > copy pages lower into memory so the I/O subsystem can use them). Some of
| > that is in the hard to fix for 2.4 category with the x86. There are some
| > experimental patches around but they are experimental.
|
| If you are referring to my block-highmem patch, then it's not considered
| too experiemental anymore. It's been a long time since any problems have
| been reported.
I've certainly tortured it a bit, with no problems.
| Scott, a small profile run would give us the information needed to tell
| whether this is a bounce problem or not. Boot the kernel with profile=2,
| then do a readprofile -r ; run problematic stuff ; readprofile >
| prof_data
|
| and share the prof_data.
Using this (above) profiling method shouldn't be very intrusive.
(I.e., need to reboot, but not patch and build a kernel.)
Here's another thing you could do, Scott. This patch is against
2.4.19-pre2 but probably will apply to several versions of 2.4.x
that do *not* have the block-highmem patch applied.
This patch adds bounce IO and bounce swap IO statistics
to /proc/stat .
It also prints out a message about which device is using (causing)
bounce IO. This message could easily become excessive, so if you
try this, feel free to disable that part of the patch.
bounce IO stats for block-highmem will require a different patch,
but Jens has helped me on that a bit, and I'll post it after some
more testing.
Any updated news from you on this issue, Scott?
--
~Randy
[-- Attachment #2: Type: TEXT/PLAIN, Size: 2629 bytes --]
--- linux/include/linux/kernel_stat.h.org Mon Nov 26 10:19:29 2001
+++ linux/include/linux/kernel_stat.h Thu Dec 20 13:26:50 2001
@@ -26,12 +26,14 @@
unsigned int dk_drive_wblk[DK_MAX_MAJOR][DK_MAX_DISK];
unsigned int pgpgin, pgpgout;
unsigned int pswpin, pswpout;
+ unsigned int bouncein, bounceout;
+ unsigned int bounceswapin, bounceswapout;
#if !defined(CONFIG_ARCH_S390)
unsigned int irqs[NR_CPUS][NR_IRQS];
#endif
- unsigned int ipackets, opackets;
- unsigned int ierrors, oerrors;
- unsigned int collisions;
+/// unsigned int ipackets, opackets;
+/// unsigned int ierrors, oerrors;
+/// unsigned int collisions;
unsigned int context_swtch;
};
--- linux/fs/proc/proc_misc.c.org Tue Nov 20 21:29:09 2001
+++ linux/fs/proc/proc_misc.c Thu Dec 20 13:34:44 2001
@@ -310,6 +310,12 @@
xtime.tv_sec - jif / HZ,
total_forks);
+ len += sprintf(page + len,
+ "bounce io %u %u\n"
+ "bounce swap io %u %u\n",
+ kstat.bouncein, kstat.bounceout,
+ kstat.bounceswapin, kstat.bounceswapout);
+
return proc_calc_metrics(page, start, off, count, eof, len);
}
--- linux/mm/page_io.c.org Mon Nov 19 15:19:42 2001
+++ linux/mm/page_io.c Thu Dec 20 15:59:41 2001
@@ -10,6 +10,7 @@
* Always use brw_page, life becomes simpler. 12 May 1998 Eric Biederman
*/
+#include <linux/config.h>
#include <linux/mm.h>
#include <linux/kernel_stat.h>
#include <linux/swap.h>
@@ -68,6 +69,13 @@
dev = swapf->i_dev;
} else {
return 0;
+ }
+
+ if (PageHighMem(page)) {
+ if (rw == WRITE)
+ kstat.bounceswapout++;
+ else
+ kstat.bounceswapin++;
}
/* block_size == PAGE_SIZE/zones_used */
--- linux/drivers/block/ll_rw_blk.c.org Mon Oct 29 12:11:17 2001
+++ linux/drivers/block/ll_rw_blk.c Thu Dec 20 17:45:19 2001
@@ -936,6 +936,7 @@
} while (q->make_request_fn(q, rw, bh));
}
+static int bmsg_count = 0;
/**
* submit_bh: submit a buffer_head to the block device later for I/O
@@ -953,6 +954,7 @@
void submit_bh(int rw, struct buffer_head * bh)
{
int count = bh->b_size >> 9;
+ int bounce = PageHighMem(bh->b_page);
if (!test_bit(BH_Lock, &bh->b_state))
BUG();
@@ -971,10 +973,19 @@
switch (rw) {
case WRITE:
kstat.pgpgout += count;
+ if (bounce) kstat.bounceout += count;
break;
default:
kstat.pgpgin += count;
+ if (bounce) kstat.bouncein += count;
break;
+ }
+ if (bounce) {
+ bmsg_count++;
+ if ((bmsg_count % 1000) == 1)
+ printk ("bounce io (%c) for %d:%d\n",
+ (rw == WRITE) ? 'W' : 'R',
+ MAJOR(bh->b_rdev), MINOR(bh->b_rdev));
}
}
^ permalink raw reply [flat|nested] 10+ messages in thread* Re: Performance issue on dual Athlon MP
2002-03-11 9:32 ` Jens Axboe
2002-03-11 20:13 ` Randy.Dunlap
@ 2002-03-14 15:49 ` Scott L. Burson
1 sibling, 0 replies; 10+ messages in thread
From: Scott L. Burson @ 2002-03-14 15:49 UTC (permalink / raw)
To: Jens Axboe; +Cc: linux-kernel
> From: Jens Axboe <axboe@suse.de>
> Date: Mon, 11 Mar 2002 10:32:17 +0100
>
> Scott, a small profile run would give us the information needed to tell
> whether this is a bounce problem or not. Boot the kernel with profile=2,
> then do a readprofile -r ; run problematic stuff ; readprofile >
> prof_data
>
> and share the prof_data.
Sorry for the slow reply. I've been super-busy... and will be out of town
for the next few days so responses will again be delayed.
I have, however, done the profile experiment you suggested. I thought it
might be nontrivial to get the problem to occur intentionally, and indeed it
proved to be even more involved than I guessed, but I did manage to do it.
I started enough memory-intensive processes to fill main memory (and spill
over very slightly into swap; but this is *not* a disk thrashing problem --
the disk light stays off when the machine is in its bogged-down state), and
also a couple of disk-intensive processes, like
cd /; tar clf /dev/null .
cd <an NFS-mounted partition>; du > du_output
Even then, what I saw most of the time was time spent in the kernel (as
reported by `top') between 30% and 70%, and the machine did not become
completely unresponsive. Twice, though, over the course of maybe an hour,
the machine did go into its apparently-hung state, only to reemerge in three
or four minutes (I hadn't previously realized it would recover that
quickly).
I collected a number of profiles, of which I enclose three. The first one
is from a typical interval in which the kernel time was above 50%. The
second was taken just before the machine became unresponsive, and the third
from just after; the time between them was 2 minutes, 50 seconds. Because I
neglected to reset the profile after taking the first of this pair, it is
the difference between them that is of interest.
The conclusion seems fairly clear: `kmem_cache_reap' and `locks_delete_lock'
are the primary culprits.
-- Scott
================ Profile 1 ================
4 rest_init 0.0500
3 __global_restore_flags 0.0375
1 get_cpuinfo 0.0018
3 sys_uname 0.0099
2 smp_local_timer_interrupt 0.0104
1 complete 0.0048
3 sleep_on 0.0234
2 setscheduler 0.0039
6 sys_sched_setscheduler 0.1875
1 copy_fs_struct 0.0048
1 sys_setgroups 0.0089
1 vmtruncate 0.0024
2 invalidate_list_pages2 0.0043
1 do_buffer_fdatasync 0.0052
1 add_to_page_cache 0.0069
1 sys_mremap 0.0069
2 vmalloc_area_pages 0.0050
1 kmem_slab_destroy 0.0063
2 kmem_cache_create 0.0023
1 do_ccupdate_local 0.0156
1 __kmem_cache_shrink 0.0069
29 enable_all_cpucaches 0.3625
5097 kmem_cache_reap 6.1262
1 swap_out 0.0007
1 try_to_release_page 0.0125
3 shrink_cache 0.0031
1 sys_open 0.0045
3 do_readv_writev 0.0054
1 sys_pread 0.0048
1 get_empty_filp 0.0031
4 write_some_buffers 0.0132
8 __put_unused_buffer_head 0.0238
1 __blkdev_prepare_write 0.0022
1 block_llseek 0.0063
3 bd_read_super 0.0187
1 bdget 0.0028
1 check_disk_change 0.0078
1 cdget 0.0039
1 fillonedir 0.0057
3 sys_getdents64 0.0099
1 __pollwait 0.0063
1175 locks_delete_lock 5.2455
2 flock_locks_conflict 0.0312
2 interruptible_sleep_on_locked 0.0104
1 posix_test_lock 0.0069
1 flock_lock_file 0.0026
1 locks_remove_flock 0.0069
1 dquot_initialize 0.0026
31 create_elf_tables 0.0404
1 isofs_read_inode 0.0009
1 nfs_proc_write 0.0027
2 nfs3_proc_read 0.0063
1 nfs3_proc_write 0.0026
1 nfs3_proc_symlink 0.0031
1 balance_internal 0.0004
1 journal_read_transaction 0.0007
1 tty_ioctl 0.0008
5 vortex_probe1 0.0016
2 issue_and_wait 0.0139
1 vortex_up 0.0005
1 vortex_timer 0.0009
1 program_drive_counts 0.0037
1 sys_recvmsg 0.0018
3 sys_socketcall 0.0059
1 sock_register 0.0125
1 __kfree_skb 0.0042
2 skb_copy_and_csum_datagram 0.0023
1 neigh_connected_output 0.0045
2 ip_route_input_slow 0.0009
1 ip_evictor 0.0033
1 ip_forward_options 0.0026
1 ip_build_xmit_slow 0.0008
1 tcp_sendmsg 0.0002
4 udp_sendmsg 0.0038
1 arp_constructor 0.0030
1 packet_mc_drop 0.0052
2 packet_setsockopt 0.0039
1 rpc_default_callback 0.0625
1 call_reserve 0.0063
1 tcp_write_space 0.0048
1 xprt_timer 0.0089
1 xprt_transmit 0.0057
1 do_xprt_transmit 0.0010
1 xprt_reserve 0.0035
1 xprt_release 0.0039
1 svc_setup_socket 0.0023
2 svc_create_socket 0.0066
1 svc_authenticate 0.0078
2 svcauth_null 0.0074
1 svcauth_unix 0.0028
555 rwsem_wake 0.0511
7028 total 0.0049
================ Profile 2 ================
4 rest_init 0.0500
12 __switch_to 0.0536
1 get_wchan 0.0089
1 __up 0.0312
1 sys_rt_sigreturn 0.0030
1 handle_signal 0.0039
15 lcall7 0.1974
8 lcall27 0.1053
6 ret_from_exception 0.2400
2 do_simd_coprocessor_error 0.0156
65 __global_restore_flags 0.8125
9 get_cpuinfo 0.0165
2 sys_pipe 0.0104
8 sys_uname 0.0263
1 pci_free_consistent 0.0312
3 setup_APIC_timer 0.0144
1 setup_profiling_timer 0.0156
1 smp_apic_timer_interrupt 0.0037
36 smp_local_timer_interrupt 0.1875
10 search_exception_table 0.0694
3 reschedule_idle 0.0059
1 schedule 0.0007
10 __wake_up 0.0446
1 __wake_up_sync 0.0037
29 complete 0.1394
1 interruptible_sleep_on_timeout 0.0078
122 sleep_on 0.9531
16 sleep_on_timeout 0.1250
3 scheduling_functions_end_here 0.1875
16 sys_nice 0.1429
37 setscheduler 0.0723
62 sys_sched_setscheduler 1.9375
4 sys_sched_rr_get_interval 0.0114
6 copy_mm 0.0075
5 copy_fs_struct 0.0240
1 do_fork 0.0006
1 sys_wait4 0.0010
4 do_adjtimex 0.0044
1 sys_adjtimex 0.0030
122 ksoftirqd 0.5865
7 request_resource 0.0875
2 release_resource 0.0417
5 find_resource 0.0284
2 __request_region 0.0125
1 ptrace_writedata 0.0057
6 del_timer_sync 0.0417
1 tqueue_bh 0.0312
9 second_overflow 0.0165
9 timer_bh 0.0125
17 sys_nanosleep 0.0226
4 kill_pg_info 0.0357
1 wake_up_parent 0.0208
4 sys_setgroups 0.0357
1 request_module 0.0021
1 sys_getgroups16 0.0078
2 clear_page_tables 0.0078
6 copy_page_range 0.0139
1 zap_page_range 0.0011
7 do_wp_page 0.0067
7 vmtruncate 0.0168
1 do_swap_page 0.0022
5 do_anonymous_page 0.0142
2 pte_alloc 0.0083
1 make_pages_present 0.0104
1 sys_brk 0.0037
10 vma_merge 0.0347
5 do_mmap_pgoff 0.0041
4 get_unmapped_area 0.0132
8 do_munmap 0.0135
3 truncate_list_pages 0.0055
20 invalidate_list_pages2 0.0431
1 waitfor_one_page 0.0156
2 do_buffer_fdatasync 0.0104
13 add_to_page_cache_locked 0.1016
11 add_to_page_cache 0.0764
1 add_to_page_cache_unique 0.0069
1 page_cache_read 0.0048
2 __find_get_page 0.0250
1 __find_lock_page 0.0057
1 mark_page_accessed 0.0208
72 __do_generic_file_read 0.0529
1 generic_file_direct_IO 0.0020
1 file_read_actor 0.0042
1 madvise_fixup_start 0.0039
2 madvise_fixup_end 0.0078
1 madvise_willneed 0.0027
1 madvise_dontneed 0.0208
3 do_mremap 0.0020
35 sys_mremap 0.2431
4 vmfree_area_pages 0.0109
1 __vmalloc 0.0020
63 vmalloc_area_pages 0.1575
5 kmem_cache_estimate 0.0347
23 kmem_slab_destroy 0.1437
69 kmem_cache_create 0.0799
2 smp_call_function_all_cpus 0.0417
2 do_ccupdate_local 0.0312
19 __kmem_cache_shrink 0.1319
2 kmem_cache_destroy 0.0074
2 free_block 0.0083
7 kmem_cache_alloc 0.0230
19 kmem_cache_free 0.1484
3 kfree 0.0208
1 kmem_tune_cpucache 0.0033
240 enable_all_cpucaches 3.0000
31815 kmem_cache_reap 38.2392
7 proc_getdata 0.0125
1 slabinfo_read_proc 0.0125
1 activate_page_nolock 0.0057
4 lru_cache_add 0.0357
1 __lru_cache_del 0.0045
28 swap_out 0.0203
27 shrink_cache 0.0281
3 refill_inactive 0.0099
7 check_classzone_need_balance 0.1458
1 rw_swap_page_base 0.0023
3 shmem_file_write 0.0035
1 shmem_file_read 0.0078
1 shmem_statfs 0.0104
2 kmap_high 0.0057
4 create_bounce 0.0089
1 sys_statfs 0.0037
8 sys_fstatfs 0.0312
2 do_truncate 0.0104
5 sys_truncate 0.0098
5 sys_truncate64 0.0098
11 sys_ftruncate64 0.0430
1 sys_access 0.0033
10 dentry_open 0.0250
19 get_unused_fd 0.0475
15 sys_open 0.0670
1 filp_close 0.0063
2 sys_close 0.0156
39 do_readv_writev 0.0696
15 sys_pread 0.0721
11 get_empty_filp 0.0344
2 fput 0.0078
2 fget 0.0250
1 put_filp 0.0104
2 __wait_on_buffer 0.0125
1 end_buffer_io_sync 0.0104
5 write_some_buffers 0.0164
1 invalidate_inode_buffers 0.0089
3 getblk 0.0082
1 balance_dirty 0.0125
5 __refile_buffer 0.0521
4 __bforget 0.0179
2 bread 0.0179
62 __put_unused_buffer_head 0.1845
2 try_to_free_buffers 0.0050
4 get_filesystem_info 0.0035
9 drop_super 0.0938
7 sync_supers 0.0230
1 chroot_fs_refs 0.0025
1 sys_pivot_root 0.0011
12 blkdev_readpage 0.0183
35 __blkdev_prepare_write 0.0781
8 blkdev_prepare_write 0.0714
5 __blkdev_commit_write 0.0284
1 block_llseek 0.0063
2 __block_fsync 0.0312
22 bd_read_super 0.1375
4 bdget 0.0114
7 bdput 0.0437
1 bd_acquire 0.0052
1 get_blkdev_list 0.0104
4 get_blkfops 0.0500
1 register_blkdev 0.0078
1 check_disk_change 0.0078
7 blkdev_get 0.0219
16 blkdev_put 0.0400
2 blkdev_close 0.0625
2 blkdev_ioctl 0.0312
6 cdget 0.0234
2 cp_new_stat 0.0042
1 sys_newstat 0.0089
1 sys_fstat 0.0104
1 sys_newfstat 0.0104
1 pipe_release 0.0069
1 permission 0.0078
4 cached_lookup 0.0417
4 follow_up 0.0278
3 path_walk 0.0015
1 set_fs_altroot 0.0022
4 path_init 0.0109
2 lookup_hash 0.0089
1 lookup_one_len 0.0089
1 __user_walk 0.0104
5 vfs_create 0.0130
22 open_namei 0.0130
1 do_fcntl 0.0015
2 sys_fcntl64 0.0139
18 sys_ioctl 0.0230
17 dcache_readdir 0.0590
10 fillonedir 0.0568
7 old_readdir 0.0729
2 filldir64 0.0052
33 sys_getdents64 0.1086
10 poll_freewait 0.1250
4 __pollwait 0.0250
53 max_select_fd 0.3011
12 do_select 0.0227
1 sys_select 0.0007
3 do_pollfd 0.0208
1 sys_poll 0.0012
2 fifo_open 0.0028
1 locks_alloc_lock 0.0125
1 locks_copy_lock 0.0089
17 lease_alloc 0.0708
3 locks_delete_block 0.0375
8048 locks_delete_lock 35.9286
5 locks_conflict 0.0781
3 posix_locks_conflict 0.0234
9 flock_locks_conflict 0.1406
43 interruptible_sleep_on_locked 0.2240
7 posix_test_lock 0.0486
15 posix_locks_deadlock 0.1339
4 locks_mandatory_locked 0.0312
11 locks_mandatory_area 0.0264
21 flock_lock_file 0.0547
6 posix_lock_file 0.0046
2 fcntl_setlk64 0.0039
1 write_inode_now 0.0018
1 find_free_dqentry 0.0020
2 dquot_initialize 0.0052
1 dquot_transfer 0.0010
1 sys_quotactl 0.0010
2 create_aout_tables 0.0046
2 load_aout_binary 0.0012
6 load_script 0.0134
699 create_elf_tables 0.9102
4 load_elf_interp 0.0053
4 isofs_get_block 0.0078
3 isofs_read_level3_size 0.0039
3 isofs_read_inode 0.0028
1 isofs_name_translate 0.0089
4 get_acorn_filename 0.0167
4 get_rock_ridge_filename 0.0046
1 parse_rock_ridge_inode_internal 0.0007
6 rock_ridge_symlink_readpage 0.0050
4 nfs_zap_caches 0.0250
1 nfs_invalidate_inode 0.0312
2 nfs_fill_inode 0.0050
3 nfs_find_actor 0.0312
5 __nfs_revalidate_inode 0.0087
10 __nfs_refresh_inode 0.0120
3 nfs_proc_write 0.0082
4 nfs_proc_mknod 0.0104
1 nfs_xdr_symlinkargs 0.0035
2 nfs_xdr_writeres 0.0417
3 nfs_xdr_statfsres 0.0075
1 nfs3_proc_lookup 0.0030
11 nfs3_proc_read 0.0344
4 nfs3_proc_write 0.0104
4 nfs3_proc_link 0.0132
4 nfs3_proc_symlink 0.0125
5 nfs3_proc_mkdir 0.0156
3 nlmclt_encode_cancargs 0.0156
1 find_forward 0.0022
30 balance_leaf 0.0032
6 linear_search_in_dir_item 0.0091
1 reiserfs_find_entry 0.0031
1 reiserfs_add_entry 0.0008
13 reiserfs_rename 0.0070
2 reiserfs_delete_inode 0.0089
3 _make_cpu_key 0.0156
1 _get_block_create_0 0.0006
2 inode2sd_v1 0.0179
1 reiserfs_fh_to_dentry 0.0025
6 reiserfs_dentry_to_fh 0.0417
5 reiserfs_write_inode 0.0284
1 leaf_item_bottle 0.0008
2 internal_delete_pointers_items 0.0057
43 internal_copy_pointers_items 0.0814
2 internal_move_pointers_items 0.0179
51 balance_internal 0.0207
8 pathrelse_and_restore 0.1250
2 reiserfs_delete_solid_item 0.0042
1 copy_short_key 0.0312
1 copy_item_head 0.0312
3 comp_keys 0.0041
1 keyed_hash 0.0010
5 journal_read_transaction 0.0034
1 reiserfs_journal_commit_thread 0.0035
1 do_journal_begin_r 0.0018
1 write_port 0.0078
1 tty_read 0.0035
1 tiocsti 0.0078
1 tiocgwinsz 0.0057
1 tiocsctty 0.0042
2 tty_ioctl 0.0016
7 n_tty_receive_buf 0.0017
1 change_termios 0.0025
7 n_tty_ioctl 0.0052
1 raw_open 0.0025
1 fasync_qp 0.0208
2 rtc_interrupt 0.0125
6 rtc_ioctl 0.0027
94 vortex_probe1 0.0304
84 issue_and_wait 0.5833
226 vortex_up 0.1167
23 vortex_open 0.0496
23 vortex_timer 0.0205
1 vortex_tx_timeout 0.0018
1 vortex_error 0.0013
3 vortex_down 0.0156
8 eth_mac_addr 0.1000
7 init_fddidev 0.2188
1 register_netdev 0.0089
21 fc_setup 0.2188
1 register_fcdev 0.0625
12 init_hwif_data 0.0250
1 ide_output_data 0.0057
69 drive_is_ready 0.8625
1 program_drive_counts 0.0037
2 cmd640_set_mode 0.0074
3 cmd640_tune_drive 0.0089
45 cmd64x_get_info 0.0281
101 proc_ide_write_config 0.0942
1 proc_ide_read_config 0.0027
2 vgacon_set_cursor_size 0.0096
1 vga_vesa_blank 0.0018
2 fbcon_getxy 0.0083
6 vesafb_set_disp 0.0197
5 md_ioctl 0.0022
1 md_register_thread 0.0057
1 md_unregister_thread 0.0104
1 sockfs_delete_dentry 0.0625
8 sock_fasync 0.0102
5 sock_wake_async 0.0391
5 sys_socketpair 0.0149
9 sys_bind 0.0703
2 sys_listen 0.0250
13 sys_recvmsg 0.0232
12 sock_fcntl 0.1875
37 sys_socketcall 0.0723
1 sock_register 0.0125
2 sk_alloc 0.0208
33 sk_free 0.2578
3 sock_init_data 0.0094
1 skb_under_panic 0.0156
1 alloc_skb 0.0023
6 skb_release_data 0.0536
2 kfree_skbmem 0.0179
2 __kfree_skb 0.0083
1 wait_for_packet 0.0031
15 skb_recv_datagram 0.0625
1 skb_copy_datagram_iovec 0.0019
24 skb_copy_and_csum_datagram 0.0273
2 skb_copy_and_csum_datagram_iovec 0.0089
4 datagram_poll 0.0179
1 dev_mc_read_proc 0.0022
1 neigh_resolve_output 0.0018
20 neigh_connected_output 0.0893
15 neigh_fill_info 0.0218
3 neigh_dump_info 0.0170
5 neigh_sysctl_register 0.0136
21 ip_route_input_slow 0.0097
4 ip_route_output_slow 0.0023
8 afinet_get_info 0.0357
7 snmp_get_info 0.0190
1 netstat_get_info 0.0069
1 inet_add_protocol 0.0052
2 inet_del_protocol 0.0063
1 ip_frag_create 0.0052
1 ip_frag_queue 0.0012
10 ip_forward_options 0.0260
1 ip_options_rcv_srr 0.0028
1 ip_build_and_send_pkt 0.0024
12 ip_queue_xmit 0.0101
8 ip_build_xmit_slow 0.0067
4 ip_getsockopt 0.0015
1 do_tcp_sendpages 0.0004
2 tcp_sendmsg 0.0005
2 tcp_rcv_state_process 0.0008
1 tcp_write_wakeup 0.0021
1 tcp_out_of_resources 0.0028
1 tcp_v4_connect 0.0011
1 tcp_v4_syn_recv_sock 0.0015
14 udp_sendmsg 0.0135
1 udp_ioctl 0.0057
7 udp_recvmsg 0.0125
8 udp_connect 0.0156
27 udp_rcv 0.0392
1 get_udp_sock 0.0052
3 udp_get_info 0.0110
3 udp_v4_lookup 0.0375
5 arp_mc_map 0.0260
2 arp_hash 0.0417
7 arp_constructor 0.0208
5 inet_ioctl 0.0098
1 unix_release_sock 0.0015
1 unix_getname 0.0042
7 packet_mc_add 0.0199
6 packet_mc_drop 0.0312
12 packet_setsockopt 0.0234
2 packet_getsockopt 0.0066
23 packet_notifier 0.0757
2 packet_ioctl 0.0020
1 packet_poll 0.0057
1 packet_mm_open 0.0208
1 free_pg_vec 0.0063
13 packet_set_ring 0.0099
12 packet_mmap 0.0268
4 rpc_clnt_sigmask 0.0250
2 rpc_clnt_sigunmask 0.0179
5 rpc_call_sync 0.0284
15 rpc_call_async 0.0852
14 rpc_call_setup 0.1250
11 call_reserve 0.0688
4 call_reserveresult 0.0179
8 call_verify 0.0156
4 xprt_lock_write 0.0179
6 xprt_release_write 0.0417
2 xprt_adjust_cwnd 0.0078
1 xprt_close 0.0078
2 xprt_disconnect 0.0250
24 xprt_reconnect 0.0333
10 xprt_reconn_status 0.1562
9 csum_partial_copy_to_page_cache 0.0331
3 tcp_input_record 0.0025
4 __rpciod_tcp_dispatcher 0.0147
4 tcp_data_ready 0.0104
12 tcp_state_change 0.0469
4 tcp_write_space 0.0192
2 xprt_timer 0.0179
6 xprt_transmit 0.0341
39 do_xprt_transmit 0.0375
3 xprt_receive 0.0312
12 xprt_reserve 0.0417
1 xprt_request_init 0.0069
9 xprt_release 0.0352
3 xprt_setup 0.0059
3 xprt_create_proto 0.0312
1 xprt_clear_backlog 0.0125
2 rpc_run_timer 0.0139
1 rpc_wake_up_next 0.0063
2 rpc_wake_up 0.0156
9 __rpc_execute 0.0100
1 rpc_execute 0.0089
8 __rpc_schedule 0.0161
6 rpc_release_task 0.0114
4 rpc_child_exit 0.0250
3 rpc_run_child 0.0057
2 svc_tcp_recvfrom 0.0014
9 svc_send 0.0201
26 svc_setup_socket 0.0602
37 svc_create_socket 0.1217
34 svc_authenticate 0.2656
1 svc_auth_register 0.0208
111 svcauth_null 0.4081
25 svcauth_unix 0.0710
3 xdr_encode_netobj 0.0268
3 xdr_decode_netobj_fixed 0.0312
1 xdr_decode_netobj 0.0208
1 xdr_encode_array 0.0089
9 xdr_decode_string_inplace 0.1875
5 xdr_shift_iovec 0.0260
4 rpc_proc_read 0.0125
2 svc_proc_read 0.0063
2 rpc_proc_register 0.0250
1 memcpy 0.0156
1 fast_clear_page 0.0125
3765 rwsem_wake 0.3467
48709 total 0.0336
================ Profile 3 ================
4 rest_init 0.0500
13 __switch_to 0.0580
1 sys_fork 0.0312
1 get_wchan 0.0089
1 __up 0.0312
1 sys_rt_sigreturn 0.0030
1 handle_signal 0.0039
17 lcall7 0.2237
8 lcall27 0.1053
7 ret_from_exception 0.2800
1 reschedule 0.0833
2 do_simd_coprocessor_error 0.0156
65 __global_restore_flags 0.8125
9 get_cpuinfo 0.0165
2 sys_pipe 0.0104
8 sys_uname 0.0263
1 pci_free_consistent 0.0312
3 setup_APIC_timer 0.0144
2 setup_profiling_timer 0.0312
2 smp_apic_timer_interrupt 0.0074
51 smp_local_timer_interrupt 0.2656
10 search_exception_table 0.0694
3 reschedule_idle 0.0059
1 schedule 0.0007
11 __wake_up 0.0491
2 __wake_up_sync 0.0074
32 complete 0.1538
1 interruptible_sleep_on_timeout 0.0078
130 sleep_on 1.0156
19 sleep_on_timeout 0.1484
3 scheduling_functions_end_here 0.1875
16 sys_nice 0.1429
40 setscheduler 0.0781
66 sys_sched_setscheduler 2.0625
4 sys_sched_rr_get_interval 0.0114
6 copy_mm 0.0075
5 copy_fs_struct 0.0240
1 do_fork 0.0006
1 sys_wait4 0.0010
5 do_adjtimex 0.0055
1 sys_adjtimex 0.0030
144 ksoftirqd 0.6923
7 request_resource 0.0875
2 release_resource 0.0417
5 find_resource 0.0284
2 __request_region 0.0125
1 ptrace_writedata 0.0057
6 del_timer_sync 0.0417
1 tqueue_bh 0.0312
10 second_overflow 0.0184
10 timer_bh 0.0139
18 sys_nanosleep 0.0239
5 kill_pg_info 0.0446
1 wake_up_parent 0.0208
5 sys_setgroups 0.0446
1 request_module 0.0021
2 sys_getgroups16 0.0156
2 clear_page_tables 0.0078
6 copy_page_range 0.0139
1 zap_page_range 0.0011
1 unlock_kiovec 0.0078
7 do_wp_page 0.0067
7 vmtruncate 0.0168
1 do_swap_page 0.0022
5 do_anonymous_page 0.0142
2 pte_alloc 0.0083
1 make_pages_present 0.0104
1 sys_brk 0.0037
10 vma_merge 0.0347
5 do_mmap_pgoff 0.0041
4 get_unmapped_area 0.0132
8 do_munmap 0.0135
3 truncate_list_pages 0.0055
32 invalidate_list_pages2 0.0690
1 waitfor_one_page 0.0156
2 do_buffer_fdatasync 0.0104
13 add_to_page_cache_locked 0.1016
11 add_to_page_cache 0.0764
1 add_to_page_cache_unique 0.0069
1 page_cache_read 0.0048
2 __find_get_page 0.0250
1 __find_lock_page 0.0057
1 mark_page_accessed 0.0208
72 __do_generic_file_read 0.0529
1 generic_file_direct_IO 0.0020
1 file_read_actor 0.0042
1 madvise_fixup_start 0.0039
2 madvise_fixup_end 0.0078
1 madvise_willneed 0.0027
1 madvise_dontneed 0.0208
3 do_mremap 0.0020
36 sys_mremap 0.2500
5 vmfree_area_pages 0.0136
1 __vmalloc 0.0020
64 vmalloc_area_pages 0.1600
5 kmem_cache_estimate 0.0347
24 kmem_slab_destroy 0.1500
70 kmem_cache_create 0.0810
2 smp_call_function_all_cpus 0.0417
3 do_ccupdate_local 0.0469
26 __kmem_cache_shrink 0.1806
2 kmem_cache_destroy 0.0074
2 free_block 0.0083
9 kmem_cache_alloc 0.0296
19 kmem_cache_free 0.1484
3 kfree 0.0208
1 kmem_tune_cpucache 0.0033
333 enable_all_cpucaches 4.1625
46681 kmem_cache_reap 56.1070
7 proc_getdata 0.0125
1 slabinfo_read_proc 0.0125
1 activate_page_nolock 0.0057
4 lru_cache_add 0.0357
1 __lru_cache_del 0.0045
29 swap_out 0.0211
51 shrink_cache 0.0531
3 refill_inactive 0.0099
7 check_classzone_need_balance 0.1458
1 rw_swap_page_base 0.0023
3 shmem_file_write 0.0035
1 shmem_file_read 0.0078
1 shmem_statfs 0.0104
2 kmap_high 0.0057
4 create_bounce 0.0089
1 sys_statfs 0.0037
8 sys_fstatfs 0.0312
2 do_truncate 0.0104
5 sys_truncate 0.0098
5 sys_truncate64 0.0098
11 sys_ftruncate64 0.0430
1 sys_access 0.0033
10 dentry_open 0.0250
20 get_unused_fd 0.0500
15 sys_open 0.0670
1 filp_close 0.0063
2 sys_close 0.0156
39 do_readv_writev 0.0696
16 sys_pread 0.0769
12 get_empty_filp 0.0375
2 fput 0.0078
2 fget 0.0250
1 put_filp 0.0104
2 __wait_on_buffer 0.0125
1 end_buffer_io_sync 0.0104
8 write_some_buffers 0.0263
1 invalidate_inode_buffers 0.0089
3 getblk 0.0082
1 balance_dirty 0.0125
5 __refile_buffer 0.0521
4 __bforget 0.0179
2 bread 0.0179
81 __put_unused_buffer_head 0.2411
2 try_to_free_buffers 0.0050
4 get_filesystem_info 0.0035
9 drop_super 0.0938
7 sync_supers 0.0230
1 chroot_fs_refs 0.0025
2 sys_pivot_root 0.0022
12 blkdev_readpage 0.0183
35 __blkdev_prepare_write 0.0781
8 blkdev_prepare_write 0.0714
5 __blkdev_commit_write 0.0284
1 block_llseek 0.0063
2 __block_fsync 0.0312
23 bd_read_super 0.1437
4 bdget 0.0114
7 bdput 0.0437
1 bd_acquire 0.0052
1 get_blkdev_list 0.0104
4 get_blkfops 0.0500
1 register_blkdev 0.0078
1 check_disk_change 0.0078
7 blkdev_get 0.0219
17 blkdev_put 0.0425
2 blkdev_close 0.0625
2 blkdev_ioctl 0.0312
6 cdget 0.0234
1 cp_old_stat 0.0022
2 cp_new_stat 0.0042
1 sys_newstat 0.0089
1 sys_fstat 0.0104
1 sys_newfstat 0.0104
1 pipe_release 0.0069
1 permission 0.0078
4 cached_lookup 0.0417
4 follow_up 0.0278
3 path_walk 0.0015
1 set_fs_altroot 0.0022
4 path_init 0.0109
2 lookup_hash 0.0089
1 lookup_one_len 0.0089
1 __user_walk 0.0104
5 vfs_create 0.0130
22 open_namei 0.0130
1 lookup_create 0.0089
1 do_fcntl 0.0015
2 sys_fcntl64 0.0139
18 sys_ioctl 0.0230
18 dcache_readdir 0.0625
10 fillonedir 0.0568
7 old_readdir 0.0729
2 filldir64 0.0052
33 sys_getdents64 0.1086
10 poll_freewait 0.1250
4 __pollwait 0.0250
54 max_select_fd 0.3068
12 do_select 0.0227
1 sys_select 0.0007
3 do_pollfd 0.0208
1 sys_poll 0.0012
3 fifo_open 0.0043
1 locks_alloc_lock 0.0125
1 locks_copy_lock 0.0089
17 lease_alloc 0.0708
3 locks_delete_block 0.0375
12847 locks_delete_lock 57.3527
5 locks_conflict 0.0781
4 posix_locks_conflict 0.0312
10 flock_locks_conflict 0.1562
43 interruptible_sleep_on_locked 0.2240
7 posix_test_lock 0.0486
15 posix_locks_deadlock 0.1339
4 locks_mandatory_locked 0.0312
11 locks_mandatory_area 0.0264
21 flock_lock_file 0.0547
6 posix_lock_file 0.0046
2 fcntl_setlk64 0.0039
1 write_inode_now 0.0018
1 find_free_dqentry 0.0020
2 dquot_initialize 0.0052
1 dquot_transfer 0.0010
1 sys_quotactl 0.0010
2 create_aout_tables 0.0046
2 load_aout_binary 0.0012
6 load_script 0.0134
710 create_elf_tables 0.9245
5 load_elf_interp 0.0066
4 isofs_get_block 0.0078
3 isofs_read_level3_size 0.0039
3 isofs_read_inode 0.0028
1 isofs_name_translate 0.0089
4 get_acorn_filename 0.0167
4 get_rock_ridge_filename 0.0046
1 parse_rock_ridge_inode_internal 0.0007
6 rock_ridge_symlink_readpage 0.0050
4 nfs_zap_caches 0.0250
1 nfs_invalidate_inode 0.0312
2 nfs_fill_inode 0.0050
3 nfs_find_actor 0.0312
5 __nfs_revalidate_inode 0.0087
10 __nfs_refresh_inode 0.0120
4 nfs_proc_write 0.0109
6 nfs_proc_mknod 0.0156
1 nfs_xdr_symlinkargs 0.0035
2 nfs_xdr_writeres 0.0417
3 nfs_xdr_statfsres 0.0075
1 nfs3_proc_lookup 0.0030
13 nfs3_proc_read 0.0406
4 nfs3_proc_write 0.0104
5 nfs3_proc_link 0.0164
4 nfs3_proc_symlink 0.0125
5 nfs3_proc_mkdir 0.0156
3 nlmclt_encode_cancargs 0.0156
1 find_forward 0.0022
30 balance_leaf 0.0032
6 linear_search_in_dir_item 0.0091
1 reiserfs_find_entry 0.0031
1 reiserfs_add_entry 0.0008
13 reiserfs_rename 0.0070
2 reiserfs_delete_inode 0.0089
3 _make_cpu_key 0.0156
1 _get_block_create_0 0.0006
2 inode2sd_v1 0.0179
1 reiserfs_fh_to_dentry 0.0025
6 reiserfs_dentry_to_fh 0.0417
5 reiserfs_write_inode 0.0284
1 leaf_item_bottle 0.0008
2 internal_delete_pointers_items 0.0057
44 internal_copy_pointers_items 0.0833
2 internal_move_pointers_items 0.0179
54 balance_internal 0.0219
8 pathrelse_and_restore 0.1250
2 reiserfs_delete_solid_item 0.0042
1 copy_short_key 0.0312
1 copy_item_head 0.0312
4 comp_keys 0.0054
1 keyed_hash 0.0010
5 journal_read_transaction 0.0034
1 reiserfs_journal_commit_thread 0.0035
1 do_journal_begin_r 0.0018
1 write_port 0.0078
1 tty_read 0.0035
1 tiocsti 0.0078
1 tiocgwinsz 0.0057
1 tiocsctty 0.0042
2 tty_ioctl 0.0016
7 n_tty_receive_buf 0.0017
1 change_termios 0.0025
7 n_tty_ioctl 0.0052
1 raw_open 0.0025
1 fasync_qp 0.0208
2 rtc_interrupt 0.0125
6 rtc_ioctl 0.0027
99 vortex_probe1 0.0321
86 issue_and_wait 0.5972
230 vortex_up 0.1188
23 vortex_open 0.0496
23 vortex_timer 0.0205
1 vortex_tx_timeout 0.0018
1 vortex_error 0.0013
3 vortex_down 0.0156
8 eth_mac_addr 0.1000
8 init_fddidev 0.2500
1 register_netdev 0.0089
21 fc_setup 0.2188
1 register_fcdev 0.0625
14 init_hwif_data 0.0292
1 ide_output_data 0.0057
69 drive_is_ready 0.8625
1 program_drive_counts 0.0037
2 cmd640_set_mode 0.0074
3 cmd640_tune_drive 0.0089
45 cmd64x_get_info 0.0281
103 proc_ide_write_config 0.0961
1 proc_ide_read_config 0.0027
2 vgacon_set_cursor_size 0.0096
1 vga_vesa_blank 0.0018
2 fbcon_getxy 0.0083
1 fbcon_get_default_font 0.0104
2 vesafb_pan_display 0.0208
8 vesafb_set_disp 0.0263
5 md_ioctl 0.0022
1 md_register_thread 0.0057
1 md_unregister_thread 0.0104
1 sockfs_delete_dentry 0.0625
8 sock_fasync 0.0102
5 sock_wake_async 0.0391
6 sys_socketpair 0.0179
9 sys_bind 0.0703
2 sys_listen 0.0250
14 sys_recvmsg 0.0250
14 sock_fcntl 0.2188
38 sys_socketcall 0.0742
1 sock_register 0.0125
2 sk_alloc 0.0208
34 sk_free 0.2656
3 sock_init_data 0.0094
1 skb_under_panic 0.0156
1 alloc_skb 0.0023
7 skb_release_data 0.0625
2 kfree_skbmem 0.0179
2 __kfree_skb 0.0083
1 wait_for_packet 0.0031
15 skb_recv_datagram 0.0625
3 skb_copy_datagram_iovec 0.0057
25 skb_copy_and_csum_datagram 0.0284
2 skb_copy_and_csum_datagram_iovec 0.0089
4 datagram_poll 0.0179
1 dev_mc_read_proc 0.0022
1 neigh_resolve_output 0.0018
20 neigh_connected_output 0.0893
15 neigh_fill_info 0.0218
4 neigh_dump_info 0.0227
5 neigh_sysctl_register 0.0136
22 ip_route_input_slow 0.0102
5 ip_route_output_slow 0.0029
8 afinet_get_info 0.0357
7 snmp_get_info 0.0190
1 netstat_get_info 0.0069
1 inet_add_protocol 0.0052
2 inet_del_protocol 0.0063
1 ip_evictor 0.0033
1 ip_frag_create 0.0052
1 ip_frag_queue 0.0012
10 ip_forward_options 0.0260
1 ip_options_rcv_srr 0.0028
1 ip_build_and_send_pkt 0.0024
12 ip_queue_xmit 0.0101
8 ip_build_xmit_slow 0.0067
4 ip_getsockopt 0.0015
1 do_tcp_sendpages 0.0004
2 tcp_sendmsg 0.0005
2 tcp_rcv_state_process 0.0008
1 tcp_write_wakeup 0.0021
1 tcp_out_of_resources 0.0028
1 tcp_v4_connect 0.0011
1 tcp_v4_syn_recv_sock 0.0015
14 udp_sendmsg 0.0135
1 udp_ioctl 0.0057
7 udp_recvmsg 0.0125
8 udp_connect 0.0156
27 udp_rcv 0.0392
1 get_udp_sock 0.0052
3 udp_get_info 0.0110
3 udp_v4_lookup 0.0375
5 arp_mc_map 0.0260
2 arp_hash 0.0417
7 arp_constructor 0.0208
5 inet_ioctl 0.0098
1 unix_release_sock 0.0015
1 unix_getname 0.0042
7 packet_mc_add 0.0199
6 packet_mc_drop 0.0312
12 packet_setsockopt 0.0234
2 packet_getsockopt 0.0066
23 packet_notifier 0.0757
2 packet_ioctl 0.0020
1 packet_poll 0.0057
1 packet_mm_open 0.0208
1 packet_mm_close 0.0208
1 free_pg_vec 0.0063
14 packet_set_ring 0.0107
13 packet_mmap 0.0290
4 rpc_clnt_sigmask 0.0250
2 rpc_clnt_sigunmask 0.0179
5 rpc_call_sync 0.0284
16 rpc_call_async 0.0909
15 rpc_call_setup 0.1339
11 call_reserve 0.0688
4 call_reserveresult 0.0179
8 call_verify 0.0156
4 xprt_lock_write 0.0179
6 xprt_release_write 0.0417
2 xprt_adjust_cwnd 0.0078
1 xprt_close 0.0078
2 xprt_disconnect 0.0250
24 xprt_reconnect 0.0333
10 xprt_reconn_status 0.1562
9 csum_partial_copy_to_page_cache 0.0331
3 tcp_input_record 0.0025
4 __rpciod_tcp_dispatcher 0.0147
4 tcp_data_ready 0.0104
12 tcp_state_change 0.0469
4 tcp_write_space 0.0192
2 xprt_timer 0.0179
6 xprt_transmit 0.0341
42 do_xprt_transmit 0.0404
3 xprt_receive 0.0312
12 xprt_reserve 0.0417
1 xprt_request_init 0.0069
9 xprt_release 0.0352
3 xprt_setup 0.0059
3 xprt_create_proto 0.0312
1 xprt_clear_backlog 0.0125
2 rpc_run_timer 0.0139
1 rpc_wake_up_next 0.0063
2 rpc_wake_up 0.0156
9 __rpc_execute 0.0100
1 rpc_execute 0.0089
8 __rpc_schedule 0.0161
6 rpc_release_task 0.0114
4 rpc_child_exit 0.0250
3 rpc_run_child 0.0057
3 svc_tcp_recvfrom 0.0021
9 svc_send 0.0201
29 svc_setup_socket 0.0671
38 svc_create_socket 0.1250
35 svc_authenticate 0.2734
1 svc_auth_register 0.0208
113 svcauth_null 0.4154
27 svcauth_unix 0.0767
3 xdr_encode_netobj 0.0268
3 xdr_decode_netobj_fixed 0.0312
1 xdr_decode_netobj 0.0208
1 xdr_encode_array 0.0089
9 xdr_decode_string_inplace 0.1875
5 xdr_shift_iovec 0.0260
4 rpc_proc_read 0.0125
2 svc_proc_read 0.0063
2 rpc_proc_register 0.0250
1 memcpy 0.0156
1 fast_clear_page 0.0125
4948 rwsem_wake 0.4556
69889 total 0.0482
^ permalink raw reply [flat|nested] 10+ messages in thread