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    [W:0.035 / U:64.112 seconds]
    ©2003-2016 Jasper Spaans. hosted at Digital OceanAdvertise on this site