lkml.org 
[lkml]   [1998]   [Aug]   [8]   [last100]   RSS Feed
Views: [wrap][no wrap]   [headers]  [forward] 
 
Messages in this thread
    /
    Date
    From
    SubjectRe: 2.1.114 VFS code 5x slower than 2.0.33?!?
    On 7 Aug 1998, Andi Kleen wrote:

    > Andi Kleen <ak@muc.de> writes:
    >
    > [hate to follow myself up, but ...]
    >
    > > I repeated your tests with kernel profiling on 2.1.114:
    > >
    <snip>
    > > 382 6.28% c01396c0 ext2_readdir
    > > 463 7.62% c011b384 do_wp_page
    > > 823 13.54% c013c6e0 ext2_find_entry
    > > 953 15.68% c013ca38 ext2_add_entry
    > > 1263 20.79% c013960c ext2_check_dir_entry
    > ^^^^^^^^^^^^^^^^^^^^^^
    > This is bogus. ext2_check_dir_entry is just a small function that does
    > some check - it should never take up that much run time. Anyone have any
    > theories on this? Or is my profile hosed, can anyone else reproduce it?
    >
    > I instrumented my kernel and in about 3h of moderate X11 usage it called
    > ext2_check_dir_entry 1520890 times, which seems a bit high.
    >
    > -Andi

    Hi Andi,

    I tried ls -l from the test directory with ktracer and a 1048576 entry
    trace buffer. It fills the buffer, so it's only the last (nearly) 1000000
    function calls.

    echo > /proc/trace;(/bin/ls -l > /dev/null);dotrace > trace2

    A profile of that looks like..

    TIME% USECS-TOTAL AVG-USECS CALLS ADDRESS FUNCTION
    0.0612% 1522.31 4.73 322 c01355f3 d_lookup
    0.0777% 1935.03 0.52 3747 c01491a7 inode_getblk
    0.0833% 2074.79 3.29 630 c0125d9f __get_free_pages
    0.0934% 2324.23 0.38 6164 c012ae0a __brelse
    0.0976% 2428.45 0.39 6161 c012a77b getblk
    0.0979% 2438.01 0.40 6169 c0129fa4 get_hash_table
    0.0989% 2462.22 0.66 3747 c01495e3 ext2_getblk
    0.1045% 2600.19 0.42 6168 c012aac1 set_writetime
    0.1482% 3688.33 3.36 1097 c0125c7b free_pages
    0.1810% 4506.08 85.02 53 c01f3602 ___copy_user
    0.2510% 6247.79 32.88 190 c01f3527 __memcpy_g
    0.2733% 6803.21 1.07 6385 c012ab17 refile_buffer
    0.2967% 7385.19 55.95 132 c0136243 find_inode
    0.5184% 12903.88 2.02 6384 c0129f4b find_buffer
    0.8341% 20763.10 943.78 22 c0113d7b add_timer
    0.8640% 21506.21 51.95 414 c01f34a2 ___zero_chunk
    2.9761% 74083.18 3704.16 20 c0111753 do_check_pgt_cache
    6.9174% 172194.28 242.53 710 c011e8bd put_page
    23.8479% 593640.59 827.95 717 c010a976 ret_from_sys_call
    24.7294% 615583.22 1905.83 323 c010c107 do_IRQ
    36.0331% 896962.98 0.92 976587 c014721c ext2_check_dir_entry
    1048556 entries; 2777969.43 total usecs; 10.39% idle.

    Wanting something that would fit in the trace buffer, I went to
    /usr/src/linux and did du -s . (primed cache prior to trace).

    echo > /proc/trace;du -s .;dotrace > trace

    TIME% USECS-TOTAL AVG-USECS CALLS ADDRESS FUNCTION
    0.9259% 14743.39 1.13 13048 c01355f3 d_lookup
    0.9343% 14877.27 1.19 12531 c0124423 kmalloc
    0.9879% 15730.10 2.34 6717 c012e6db cp_new_stat
    0.9990% 15907.41 1.74 9127 c0125c7b free_pages
    1.0787% 17176.24 2.88 5968 c0136286 clean_inode
    1.0942% 17422.27 0.80 21762 c0134db3 dput
    1.4034% 22345.94 1.04 21395 c012ab17 refile_buffer
    1.5735% 25054.04 3.93 6370 c01f3527 __memcpy_g
    2.6330% 41923.71 297.33 141 c0113d7b add_timer
    4.3329% 68990.50 3.22 21398 c0129f4b find_buffer
    5.5839% 88909.66 8.95 9939 c010a976 ret_from_sys_call
    7.6587% 121945.87 207.39 588 c011e8bd put_page
    12.7650% 203252.68 32.49 6255 c0136243 find_inode
    15.3038% 243675.91 0.83 293168 c014721c ext2_check_dir_entry
    21.2154% 337805.24 4504.07 75 c0111753 do_check_pgt_cache
    803532 entries; 2364579.96 total usecs; 32.66% idle.

    Profiling by pid gives..

    TIME% USECS-TOTAL AVG-USECS CALLS ADDRESS FUNCTION+PID
    0.6747% 14543.17 1.12 12961 c01355f3 d_lookup p10399
    0.6832% 14725.76 1.18 12479 c0124423 kmalloc p10399
    0.7281% 15694.34 2.34 6707 c012e6db cp_new_stat p10399
    0.7916% 17062.58 2.72 6269 c01f3527 __memcpy_g p10399
    0.7928% 17088.70 2.87 5950 c0136286 clean_inode p10399
    0.7998% 17240.55 0.80 21655 c0134db3 dput p10399
    0.9272% 19985.35 0.99 20164 c012ab17 refile_buffer p10399
    3.0872% 66544.92 3.30 20164 c0129f4b find_buffer p10399
    3.2718% 70524.12 7.45 9471 c010a976 ret_from_sys_call p10399
    4.9131% 105900.82 362.67 292 c011e8bd put_page p10401
    9.4105% 202842.37 32.52 6237 c0136243 find_inode p10399
    11.2092% 241614.08 0.83 290949 c014721c ext2_check_dir_entry p10399
    15.6706% 337778.83 4757.45 71 c0111753 do_check_pgt_cache p0
    28.0252% 604079.67 4682.79 129 c011409b schedule p0
    803532 entries; 2155490.19 total usecs.

    I'm pretty sure that ktracer isn't broken, so I don't think it's bogus.

    -Mike


    -
    To unsubscribe from this list: send the line "unsubscribe linux-kernel" in
    the body of a message to majordomo@vger.rutgers.edu
    Please read the FAQ at http://www.altern.org/andrebalsa/doc/lkml-faq.html

    \
     
     \ /
      Last update: 2005-03-22 13:43    [W:0.025 / U:61.484 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site