svn commit: r187132 - head/usr.bin/make

[David O'Brien]

On Fri, Jan 30, 2009 at 09:30:52AM -0700, M. Warner Losh wrote:
> OMG!  There's too much make output now, and the recent changes broke
> useful make features.  All but one were eventually fixed.  I just
> fixed the -s breakage.

I fail to see where 'make -Q -s' is not suitable to achieve the goals
you mentioned for 'make -s'.  I did make sure you could quiet things.


I've tried to measure the "~10% performance improvement" in using
'make -s' that was the technical justification for r187921.  I have
been unable to achieve ~10%.  The summary is:
        'make -j16 -Q -s' saves 2.54% over 'make -j16' on local disk.
        'make -s' saves 0.96% over 'make' on local disk.
        results on NFS are insignificant [ delta < 0.5% ].


I ran benchmarks on ref8-amd64 (a machine others have access to and
can audit my results).  I checked out
svn+ssh://svn.freebsd.org/base/head@187920 and built make from that.
Using that make I then ran buildworld's.

The abbreviated results for local disk are:

MAKE=make at r187921 /usr/bin/time -h $MAKE -j16 -Q buildworld >outfile 2>&1
        25m38.07s real          1h30m6.59s user         45m37.27s sys
        25m15.23s real          1h30m1.67s user         45m28.50s sys
        25m22.65s real          1h30m8.85s user         45m32.10s sys
        (1538.07 + 1515.23 + 1522.65)/3 = 1525.32 sec ave
        [10% improvement would reduce build by 2m33s]

MAKE=make at r187921 /usr/bin/time -h $MAKE -j16 -Q -s buildworld >outfile 2>&1
        24m36.12s real     1h27m27.18s user     44m26.88s sys
        24m34.77s real     1h27m27.82s user     44m24.56s sys
        24m29.01s real     1h27m22.16s user     44m28.23s sys
        (1476.12 + 1474.77 + 1469.01)/3 = 1473.30 sec ave
        => 1473.30 / 1525.32 * 100 - 100 = -3.41% change in build time

        [compared with below]
        => 1473.30 / 1511.70 * 100 - 100 = -2.54% change in build time

MAKE=make at r187921 /usr/bin/time -h $MAKE -j16 buildworld >outfile 2>&1
        25m3.95s real      1h27m40.02s user     45m19.12s sys
        24m57.35s real     1h27m33.31s user     45m6.81s sys
        25m33.81s real     1h27m39.68s user     44m50.02s sys
        (1503.95 + 1497.35 + 1533.81)/3 = 1511.70 sec ave
        => 1511.70 / 1525.32 * 100 - 100 = -.89% change in build time

MAKE=make at r187921 /usr/bin/time -h $MAKE buildworld >outfile 2>&1
        1h48m7.30s real	   1h28m22.07s user     22m28.01s sys
        1h48m0.94s real	   1h28m35.60s user     22m7.59s sys
        1h48m4.20s real	   1h28m39.28s user     21m58.27s sys
        (6487.30 + 6480.94 + 6484.20)/3 = 6484.15 sec ave
        [10% improvement would reduce build by 10m48s]

MAKE=make at r187921 /usr/bin/time -h $MAKE -s buildworld >outfile 2>&1
        1h47m56.48s real   1h28m35.91s user     22m0.57s sys
        1h47m55.65s real   1h28m40.66s user     21m56.70s sys
        1h51m5.05s real	   1h28m48.22s user     22m21.96s sys
        (6476.48 + 6475.65 + 6665.05)/3 = 6539.06 sec ave
        => 6539.06 / 6484.15 * 100 - 100 = .85% change in build time
        If we toss out the high value and use 6476.48 twice, ave = 6476.20
        => 6476.20 / 6539.06 * 100 - 100 = -.96% change in build time


The NFS results are:

MAKE=make at r187921 /usr/bin/time -h $MAKE -j16 buildworld >outfile 2>&1
        35m33.59s real     1h33m20.08s user     52m1.04s sys
        31m9.58s real      1h33m43.16s user     52m41.46s sys
        31m18.94s real     1h33m40.45s user     52m41.58s sys
        (2133.59 + 1869.58 + 1878.94)/3 = 1960.70 sec ave

MAKE=make at r187921 /usr/bin/time -h $MAKE -j16 -Q -s buildworld >outfile 2>&1
        31m42.62s real     1h33m28.64s user     52m4.32s sys
        31m14.54s real     1h33m21.25s user     52m8.88s sys
        31m17.26s real     1h33m22.48s user     52m10.93s sys
        (1902.62 + 1874.54 + 1877.26)/3 = 1884.81 sec ave
        => 1884.81 / 1960.70 * 100 - 100 = -3.87% change in build time

        To be fair as in the local disk case, redoing the above:
        (1878.94 + 1869.58 + 1878.94)/3 = 1875.82 sec ave (adjusted)
        => 1884.81 / 1875.82 * 100 - 100 = .48% change in build time

MAKE=make at r187921 /usr/bin/time -h $MAKE buildworld >outfile 2>&1
        2h21m30.74s real   1h30m28.41s user     29m8.64s sys
        2h21m2.15s real    1h30m25.54s user     29m2.99s sys
        2h21m0.24s real    1h30m25.93s user     29m3.85s sys
        (8490.74 + 8462.15 + 8460.24)/3 = 8471.04 sec ave

MAKE=make at r187921 /usr/bin/time -h $MAKE -s buildworld >outfile 2>&1
        2h20m48.71s real   1h30m26.02s user     29m7.66s sys
        2h21m5.95s real    1h30m21.87s user     29m10.28s sys
        2h21m7.70s real    1h30m29.85s user     29m4.29s sys
        (8448.71 + 8465.95 + 8467.7)/3 = 8460.79 sec ave
        => 8460.79 /8471.04 * 100 - 100 = -.12% change in build time


Thus I think there isn't any real time savings with "-Q -s"/"-s".
Granted I was not in full control of the machine to ensure there was no
completing usage, but from what I can other users didn't adversely affect
my results.  Also, three samples is rather small; but I was working from
very little data from the "~10% performance improvement".


I also "benchmarked" log size to see how much an issue that is:

/usr/bin/time -h make at r187921 -j16 buildworld
        30692989 , 30076086 , 30039499  (29M)
/usr/bin/time -h $MAKE -j16 -Q buildworld
        27734095, 27169263, 27169297  (26M)
/usr/bin/time -h $MAKE -j16 -s buildworld
        1168471 , 1168346 , 1165518  (1.1M)
/usr/bin/time -h make at r187921 -j16 -Q -s buildworld
        925073 , 925072 , 925103  (903K)
/usr/bin/time -h make at r187921 buildworld
        27168710 , 27168709 , 27168710  (26M)
/usr/bin/time -h make at r187921 -s buildworld
        924919 , 924920 , 924919  (903K)

I do not consider the 3M of additional output of 'make -j16' vs.
'make -j16 -Q' to be significant with today's disk sizes.

-- 
-- David