mirror of https://lore.kernel.org/lkml/
 help / color / mirror / Atom feed
From: "Scott L. Burson" <gyro@zeta-soft.com>
To: Jens Axboe <axboe@suse.de>
Cc: linux-kernel@vger.kernel.org
Subject: Re: Performance issue on dual Athlon MP
Date: Thu, 14 Mar 2002 07:49:15 -0800 (PST)	[thread overview]
Message-ID: <15504.49857.286911.772438@kali.zeta-soft.com> (raw)
In-Reply-To: <20020311093217.GB31108@suse.de>
In-Reply-To: <15494.32860.773969.762627@kali.zeta-soft.com> <E16j7Yh-0004CL-00@the-village.bc.nu> <20020311093217.GB31108@suse.de>

> 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

  parent reply	other threads:[~2002-03-14 15:49 UTC|newest]

Thread overview: 10+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2002-03-06 19:28 Dieter Nützel
2002-03-06 20:49 ` John Jasen
2002-03-07 23:20 ` Scott L. Burson
2002-03-07 23:44   ` Alan Cox
2002-03-08  0:24     ` Randy.Dunlap
2002-03-11  9:32     ` Jens Axboe
2002-03-11 20:13       ` Randy.Dunlap
2002-03-14 15:49     ` Scott L. Burson [this message]
  -- strict thread matches above, loose matches on Subject: below --
2002-03-06 22:09 rwhron
2002-03-06 18:47 Scott L. Burson

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=15504.49857.286911.772438@kali.zeta-soft.com \
    --to=gyro@zeta-soft.com \
    --cc=axboe@suse.de \
    --cc=linux-kernel@vger.kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body.
This is a public inbox, see mirroring instructions
for how to clone and mirror all data and code used for this inbox

all inboxes | Powered by JetHome®