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.071 / U:1.604 seconds]
©2003-2020 Jasper Spaans|hosted at Digital Ocean and TransIP|Read the blog|Advertise on this site