lkml.org 
[lkml]   [1998]   [Aug]   [11]   [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?!? (patch attached)
On Mon, 10 Aug 1998, Bill Hawes wrote:

> Hi Mike,
>
> I rewrote ext2_check_dir_entry to move the error handling out-of-line, and
> thought you might be interested in profiling to see whether it helps at all.
>
> Even if ext2_check_dir_entry doesn't account for the long elapsed times, it
> should still be worthwhile to speed it up a bit, as your profiling results
> indicate that it does get called a lot.
>
> Regards,
> Bill

Hi Bill,

I don't see any speed difference with the patch, but I did notice something
that looks very strange. Please bear with me, as it's difficult to describe
that which you only understand little pieces of. Notice CALLS below and
remember the previous report (293168 for profiling du -s /usr/src/linux).

profiling du -s linux:

TIME% USECS-TOTAL AVG-USECS CALLS ADDRESS FUNCTION
prof1: 3.5108% 8167.04 0.85 9618 c0147244 ext2_check_dir_entry
prof2: 2.6960% 6102.58 0.86 7065 c0147244 ext2_check_dir_entry
prof3: 3.8586% 243933.56 0.83 294344 c0147244 ext2_check_dir_entry
prof4: 7.9671% 63744.33 0.85 74996 c0147244 ext2_check_dir_entry

prof1 is primed cache after fresh boot.
prof2 is re-prime and repeat.
prof3 is after putzing around in the huge test directory. (whack cache)
prof4 is re-prime and repeat.

I repeated prof4 many times.. consistent at ~75000 now. (hmm) Checked
ktracer for proper function of trace buffer; works fine, no strangeness
tracing other things. Buffer resets on command etc. Decide to measure
speed and report in a timely manner instead.. tinker with #calls later.

apply patch, check for speedup and then continue tinkering with strange
#calls problem until too late to send report :-) (connection timelock)

TIME% USECS-TOTAL AVG-USECS CALLS ADDRESS FUNCTION
profa: 2.9294% 15112.17 0.85 17711 c0147247 ext2_check_dir_entry
profb: 1.4757% 6221.63 0.87 7129 c0147247 ext2_check_dir_entry
profc: 3.9282% 247488.82 0.84 294418 c0147247 ext2_check_dir_entry
profd: 16.7667% 236475.48 0.84 280503 c0147247 ext2_check_dir_entry
profe: 14.9596% 234952.73 0.84 279692 c0147247 ext2_check_dir_entry
proff: 19.6429% 232544.38 0.84 277482 c0147247 ext2_check_dir_entry

The test order is the same as above. The only difference is that I putzed
around longer in the huge directory. This time, it went straight to max
and stayed there with no stops in between.

-Mike

P.S.

It is now 6 hours later. I killed the xmit of the original report in order
to add this additional info. I'm pretty sure that this is real since it
shows up with normal profiling, gcc profiling and ktracer.

The attached script shows the (mumble dca mrrrmph) VFS :) working solid
as a rock.. until it suddenly shows some instability and stops doing so.
Permanently. Please look at the first couple of cycles to get the general
idea, and then search for 'interesting'.

This looks like Red Snapper to me.. could be Herring though :)

-Mike
Script started on Tue Aug 11 11:59:39 1998
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:00:05 CEST 1998
1.1466% 6045.66 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:00:50 CEST 1998
1.1696% 6166.73 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:01:37 CEST 1998
1.1632% 6158.21 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/src
2174680 /usr/local/src
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:04:30 CEST 1998
17.2072% 247801.60 0.84 296117 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:07:17 CEST 1998
16.2116% 235382.17 0.84 280811 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:10:01 CEST 1998
1.1962% 6061.72 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:10:46 CEST 1998
1.2365% 6055.87 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:11:30 CEST 1998
1.2068% 6154.55 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/src/tmp
351032 /usr/local/src/tmp
[root]:# du -s /usr/local/tmp
74612 /usr/local/tmp
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:19:25 CEST 1998
17.0116% 248242.25 0.84 296128 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:22:11 CEST 1998
13.4863% 172136.33 0.85 201541 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:24:22 CEST 1998
4.1588% 29322.55 0.89 32886 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:25:23 CEST 1998
1.2406% 6089.67 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:26:08 CEST 1998
1.2284% 6044.03 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# /bin/ls -l /usr/local/tmp > /dev/null
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:28:22 CEST 1998
16.0401% 237490.08 0.84 283029 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:31:05 CEST 1998
9.0497% 80885.00 0.86 94119 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:32:31 CEST 1998
1.1509% 6053.21 0.86 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:33:17 CEST 1998
1.2034% 6154.46 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/tmp
74612 /usr/local/tmp
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:41:08 CEST 1998
17.0548% 251833.33 0.85 296128 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:43:55 CEST 1998
12.7923% 160679.60 0.86 187699 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:46:02 CEST 1998
4.1277% 29036.99 0.89 32585 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:47:03 CEST 1998
1.1734% 6156.44 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:47:48 CEST 1998
1.2459% 6153.96 0.87 7065 c0147247 ext2_check_dir_entry
NOTE: here I try du -s /usr/local/tmp on a different terminal done
from /usr/local/tmp. no idea why.. but anyway, it recovered :)

[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:53:52 CEST 1998
16.1658% 240759.14 0.85 282814 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:56:34 CEST 1998
1.1705% 6159.46 0.87 7065 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 12:57:19 CEST 1998
1.1701% 6157.93 0.87 7065 c0147247 ext2_check_dir_entry
NOTE: here things finally start to get interesting

[root]:# du -s /usr/local/src > /dev/null
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:01:15 CEST 1998
17.3062% 246041.18 0.84 293228 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:04:14 CEST 1998
8.5302% 247466.33 0.84 293811 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:07:05 CEST 1998
0.2120% 6442.23 0.91 7075 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:08:18 CEST 1998
1.2675% 6582.21 0.86 7612 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/src > /dev/null
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:09:21 CEST 1998
1.6580% 8763.36 0.87 10043 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:10:07 CEST 1998
21.4238% 248260.45 0.84 296322 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:12:32 CEST 1998
1.8345% 9342.85 0.89 10550 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:13:30 CEST 1998
1.7931% 9523.39 0.87 10907 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:14:16 CEST 1998
1.8184% 9718.90 0.89 10935 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:15:02 CEST 1998
1.8094% 9631.83 0.88 10935 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:15:48 CEST 1998
1.8128% 9700.60 0.89 10907 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:16:42 CEST 1998
1.2944% 6439.33 0.86 7480 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > xx;profit xx|grep ext2_check_dir_entry
Tue Aug 11 13:17:32 CEST 1998
1.3728% 6444.50 0.86 7463 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:18:27 CEST 1998
1.6398% 8711.39 0.87 9977 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:19:13 CEST 1998
1.3538% 7204.09 0.88 8191 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:20:02 CEST 1998
1.8091% 9663.32 0.88 10962 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:20:49 CEST 1998
1.7978% 9691.26 0.89 10907 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:21:36 CEST 1998
1.8126% 9706.53 0.89 10935 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/src > /dev/null
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:24:53 CEST 1998
5.8993% 252105.95 0.85 297218 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:28:04 CEST 1998
10.1917% 246995.07 0.83 298231 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:31:04 CEST 1998
14.4089% 245564.84 0.83 296642 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:33:58 CEST 1998
14.4703% 245782.80 0.83 296524 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:36:53 CEST 1998
14.4577% 249162.61 0.84 296524 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace|profit|grep ext2_check_dir_entry
Tue Aug 11 13:40:54 CEST 1998
14.0251% 245722.82 0.83 296547 c0147247 ext2_check_dir_entry
[root]:# du -s /usr/local/src > /dev/null
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > yy;profit yy|grep ext2_check_dir_entry
Tue Aug 11 13:44:04 CEST 1998
16.9070% 241981.18 0.83 292371 c0147247 ext2_check_dir_entry
[root]:# date;echo > /proc/trace;du -s linux > /dev/null;dotrace > yy;profit yy|grep ext2_check_dir_entry
Tue Aug 11 13:47:02 CEST 1998
4.0027% 244860.95 0.83 293811 c0147247 ext2_check_dir_entry
NOTE: snipped some more of same.. it stays messed up forever.

[root]:# exit
exit

Script done on Tue Aug 11 14:03:10 1998
\
 
 \ /
  Last update: 2005-03-22 13:43    [from the cache]
©2003-2014 Jasper Spaans. Advertise on this site