lkml.org 
[lkml]   [1999]   [Jul]   [28]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    From
    SubjectExcessive System time in MSP kernel.
    Date
     Hello,

    I send you this after the following corrspondence:

    > "Gerlach van Beinum" <G.vanBeinum@bouw.tno.nl> writes:
    >
    > > Hello,
    > >
    > > We have a problem on a 2-processor Pentium system. The system has 512
    Mb
    > > memory. It is used to make large FEM computations. In general it
    performs
    > > well. There is one situation where it degrades fast: If we run out test
    > > suite, which consists of about 1500 small jobs, then after say 150 jobs,
    the
    > > system is mainly running in system mode ( orange in xosview ). This can
    be
    > > solved by running a small memory allocation (and initializing)job. This
    > > seems to 'flush' memory. But after the next 150 jobs, the same thing
    > > happens. We are Running RedHat 6.0 with kernel 2.5.5. Later kernels
    behave
    > > the same. What are we missing? I remember something about update or
    kflushd
    > > processes...
    >
    > You can check where in the kernel it uses the excessive time by booting
    > with profile=2 on the lilo command line; and using the /sbin/readprofile
    > tool to read the profiling statistics. Clear it before your run with
    > echo > /proc/profile, afterwards run readprofile [make sure it finds the
    > correct System.map for your kernel] and send the result to
    > linux-kernel@vger.rutgers.edu
    >
    > One possibility is that your work load is harmed by the kernel lock;
    > if this is true "stext_lock" should show prominently on the profile.
    >
    > -Andi

    readprofile produces the following results:

    4 startup_32 0.0244
    1 release_segments 0.0357
    1 copy_thread 0.0047
    6 __switch_to 0.0319
    1 sys_execve 0.0081
    1 setup_sigcontext 0.0032
    27 system_call 0.4821
    4 ret_from_sys_call 0.2353
    5 ret_with_reschedule 0.3125
    11 restore_all 0.7333
    2 ret_from_intr 0.0625
    21 error_code 0.4038
    1 device_not_available 0.0167
    110 page_fault 9.1667
    1 math_state_restore 0.0227
    4 get_irq_list 0.0109
    2 __global_cli 0.0060
    4 __global_restore_flags 0.0588
    32 handle_IRQ_event 0.2353
    1 do_gettimeofday 0.0081
    6 old_mmap 0.0227
    5 smp_flush_tlb 0.0446
    1 get_pte_slow 0.0074
    3 do_check_pgt_cache 0.0132
    792 si_meminfo 6.1875
    45 do_page_fault 0.0565
    2 flush_signal_handlers 0.0333
    2 sys_rt_sigprocmask 0.0043
    3 do_sigaction 0.0085
    1 sys_sigprocmask 0.0027
    2 sys_rt_sigaction 0.0093
    5 wake_up_process 0.0312
    1 del_timer 0.0114
    1 schedule_tail 0.0179
    62 schedule 0.0651
    5 __wake_up 0.0625
    1 interruptible_sleep_on 0.0060
    3 update_process_times 0.3750
    37 timer_bh 0.0369
    1 free_uid 0.0093
    2 get_pid 0.0063
    1 mmput 0.0192
    4 copy_files 0.0060
    17 do_fork 0.0077
    3 in_group_p 0.0500
    10 exit_notify 0.0170
    4 do_exit 0.0055
    2 sys_wait4 0.0021
    1 sys_sysinfo 0.0053
    1 get_fast_time 0.0625
    169 do_bottom_half 1.0562
    23 clear_page_tables 0.1173
    31 copy_page_range 0.0605
    61 zap_page_range 0.1374
    3 put_page 0.0750
    1 put_dirty_page 0.0025
    135 do_wp_page 0.2446
    1178 do_anonymous_page 9.2031
    29 do_no_page 0.1272
    36 handle_mm_fault 0.0783
    2 make_pages_present 0.0238
    4 vm_enough_memory 0.0312
    9 sys_brk 0.0304
    16 do_mmap 0.0165
    1 get_unmapped_area 0.0093
    1 get_unmapped_area 0.0093
    1 avl_rebalance 0.0028
    31 find_vma 0.3100
    5 find_vma_prev 0.0298
    2 unmap_fixup 0.0071
    1 free_pgtables 0.0074
    9 do_munmap 0.0163
    3 sys_munmap 0.0300
    4 exit_mmap 0.0152
    10 insert_vm_struct 0.0284
    9 merge_segments 0.0247
    8 shrink_mmap 0.0263
    285 update_vm_cache 0.9375
    3 try_to_read_ahead 0.0103
    1 __wait_on_page 0.0032
    74 do_generic_file_read 0.0481
    647 file_read_actor 8.0875
    5 generic_file_read 0.0403
    1 file_send_actor 0.0066
    215 filemap_nopage 0.2687
    1 change_protection 0.0030
    1 sys_mprotect 0.0026
    1 kmem_cache_grow 0.0010
    29 kmem_cache_alloc 0.0833
    16 kmem_cache_free 0.0392
    7 kmalloc 0.0173
    5 kfree 0.0108
    1 kmem_cache_reap 0.0017
    1 try_to_swap_out 0.0020
    1 rw_swap_page_base 0.0011
    118 __free_page 0.5086
    44 free_pages 0.1618
    151 __get_free_pages 0.3199
    3 free_page_and_swap_cache 0.0312
    1 lookup_swap_cache 0.0054
    449 si_swapinfo 2.8062
    5 sys_access 0.0171
    3 filp_open 0.0125
    7 get_unused_fd 0.0199
    12 sys_open 0.0698
    4 __fput 0.0556
    2 filp_close 0.0217
    4 sys_close 0.0294
    10 sys_llseek 0.0362
    14 sys_read 0.0603
    13 sys_write 0.0445
    1 insert_file_free 0.0250
    6 get_empty_filp 0.0197
    2 init_private_file 0.0172
    6 fput 0.0833
    7 remove_from_queues 0.0213
    14 insert_into_queues 0.0493
    54 find_buffer 0.7105
    18 get_hash_table 0.5000
    9 get_hardblocksize 0.2500
    4 init_buffer 0.0667
    1 end_buffer_io_sync 0.0227
    31 getblk 0.0566
    8 set_writetime 0.1250
    24 refile_buffer 0.1304
    18 __brelse 0.3462
    6 __bforget 0.0417
    2 put_unused_buffer_head 0.0263
    3 get_unused_buffer_head 0.0187
    164 brw_page 0.1798
    164 brw_page 0.1798
    64 mark_buffer_uptodate 0.7619
    5 generic_readpage 0.0347
    2 try_to_free_buffers 0.0152
    10 sync_old_buffers 0.0221
    1 bdflush 0.0015
    5 cp_new_stat 0.0171
    18 sys_newstat 0.1286
    1 sys_newlstat 0.0071
    7 sys_newfstat 0.0449
    1 open_dentry 0.0046
    8 copy_strings 0.0192
    1 setup_arg_pages 0.0038
    1 read_exec 0.0032
    2 flush_old_exec 0.0043
    2 search_binary_handler 0.0072
    8 getname 0.0541
    19 permission 0.0766
    3 reserved_lookup 0.0417
    2 cached_lookup 0.0263
    10 real_lookup 0.0862
    14 do_follow_link 0.1129
    36 lookup_dentry 0.0726
    4 __namei 0.0455
    9 open_namei 0.0106
    1 sys_unlink 0.0045
    1 sys_dup2 0.0015
    1 __pollwait 0.0051
    1 max_select_fd 0.0053
    1 sys_select 0.0007
    2 locks_remove_posix 0.0139
    13 dput 0.0396
    11 d_alloc 0.0327
    2 d_instantiate 0.0455
    1 d_alloc_root 0.0167
    16751 d_lookup 80.5337
    1 d_rehash 0.0147
    1 sys_getcwd 0.0071
    2 __mark_inode_dirty 0.0208
    1 __wait_on_inode 0.0047
    1 sync_inodes 0.0035
    1 clear_inode 0.0089
    3 find_inode 0.0536
    1 get_empty_inode 0.0056
    2 get_new_inode 0.0067
    1 iget 0.0083
    3 iput 0.0052
    5 update_atime 0.0500
    2 is_bad_inode 0.1000
    4 create_elf_tables 0.0050
    2 load_elf_binary 0.0006
    7 ext2_permission 0.0330
    1 ext2_get_group_desc 0.0076
    2 load__block_bitmap 0.0041
    2 ext2_free_blocks 0.0025
    27 ext2_new_block 0.0107
    1 ext2_check_dir_entry 0.0054
    2 ext2_file_lseek 0.0156
    48 ext2_file_write 0.0373
    1 ext2_release_file 0.0357
    2 ext2_open_file 0.0556
    95 ext2_alloc_block 0.2861
    3 ext2_bmap 0.0051
    11 inode_getblk 0.0239
    25 block_getblk 0.0383
    25 block_getblk 0.0383
    20 ext2_getblk 0.0382
    2 ext2_read_inode 0.0020
    3 ext2_update_inode 0.0035
    25 ext2_find_entry 0.0327
    2 ext2_add_entry 0.0024
    16 trunc_indirect 0.0231
    1 trunc_dindirect 0.0027
    1 proc_get_inode 0.0038
    7 proc_lookup 0.0312
    16 proc_root_lookup 0.0533
    1 write_profile 0.0064
    22 get_kstat 0.0327
    2 get_root_array 0.0054
    1 array_read 0.0021
    1 sock_sendmsg 0.0058
    1 sock_recvmsg 0.0056
    1 sock_write 0.0064
    2 sock_wake_async 0.0217
    2 sock_wfree 0.0714
    1 sock_wmalloc 0.0139
    1 sock_def_wakeup 0.0357
    1 sock_def_readable 0.0227
    1 alloc_skb 0.0042
    3 __kfree_skb 0.0179
    1 skb_clone 0.0066
    1 memcpy_toiovec 0.0096
    1 __scm_send 0.0021
    1 dev_queue_xmit 0.0050
    1 netif_rx 0.0054
    4 net_bh 0.0080
    1 eth_type_trans 0.0057
    1 eth_copy_and_sum 0.0069
    1 qdisc_restart 0.0093
    2 pfifo_fast_dequeue 0.0250
    1 ip_route_input 0.0034
    2 net_timer 0.0062
    1 ip_local_deliver 0.0016
    2 ip_rcv 0.0027
    1 ip_create 0.0035
    2 ip_output 0.0106
    1 ip_queue_xmit 0.0010
    1 tcp_poll 0.0039
    1 tcp_write_space 0.0119
    1 tcp_ioctl 0.0047
    1 tcp_do_sendmsg 0.0006
    1 cleanup_rbuf 0.0056
    5 tcp_recvmsg 0.0037
    1 tcp_ack 0.0012
    1 tcp_data 0.0036
    2 tcp_rcv_established 0.0013
    3 tcp_transmit_skb 0.0030
    1 tcp_write_xmit 0.0025
    1 __tcp_select_window 0.0057
    1 tcp_send_ack 0.0060
    1 tcp_v4_send_check 0.0100
    1 tcp_v4_do_rcv 0.0028
    1 tcp_v4_rcv 0.0012
    1 udp_check 0.0192
    1 udp_rcv 0.0017
    1 inet_sendmsg 0.0069
    3 inet_ioctl 0.0073
    5 ip_fw_check 0.0036
    3 ipfw_input_check 0.0312
    2 ipfw_output_check 0.0200
    2 ipfw_output_check 0.0200
    2 unplug_device 0.0227
    1 is_read_only 0.0167
    1 add_request 0.0015
    12 make_request 0.0083
    3 ll_rw_block 0.0057
    2 ide_set_handler 0.0278
    2 ide_wait_stat 0.0098
    16 ide_do_request 0.0113
    2 do_hwgroup_request 0.0217
    7 do_rw_disk 0.0104
    1 opost_block 0.0025
    2 read_chan 0.0011
    1 csum_partial 0.0064
    21 __udelay 0.2500
    2 __const_udelay 0.0357
    6 __generic_copy_to_user 0.0938
    694 __generic_copy_from_user 10.8438
    16 strncpy_from_user 0.2000
    3 clear_user 0.0417
    48 strlen_user 1.0909
    1 __get_user_1 0.0500
    2 __get_user_4 0.0833
    3 bad_get_user 0.3750
    21 number 0.0423
    39 vsprintf 0.0445
    23934 total 0.0276

    It seems to me that a lot of time is spent in d_lookup....

    x_osview tells me that I use 496M, of which more than 300M is USED+SHAR, the
    rest is evenly divided between BUFF and CACHE

    The system has 512M. My impression is that my previous system with only
    128M did run better ( in the case of running 1500 small test jobs! ). It
    looks like there is so much kept in memory, that searching in it for
    something useful is taking a lot of time.

    I want to express my gratitude for any one who spent time on this. Also for
    linux we must say: Let's make things better!

    gerlach

    Gerlach van Beinum (G.vanBeinum@bouw.tno.nl)
    PO-box 49 VOICE : +31 152842029
    2600 AA Delft(NL) FAX : +31 152843990

    PS

    I also attach the result:

    <<p>>


    [unhandled content-type:application/octet-stream]
    \
     
     \ /
      Last update: 2005-03-22 13:53    [W:0.044 / U:31.176 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site