Export to GitHub

unladen-swallow - issue #64

Major regression in startup time


Posted on Jun 24, 2009 by Helpful Elephant

2009Q1 vs trunk@r669 (-j never): perf.py options: --args ",-j never"

normal_startup: Min: 0.377 -> 0.438: 13.94% slower Avg: 0.396 -> 0.459: 13.65% slower Significant (t=-22.757922, a=0.95) Stddev: 0.007 -> 0.027: 72.96% larger

startup_nosite: Min: 0.106 -> 0.203: 47.75% slower Avg: 0.107 -> 0.205: 47.51% slower Significant (t=-493.209565, a=0.95) Stddev: 0.002 -> 0.002: 2.58% larger

This is probably due to having to load the LLVM libraries. Of course, start up time with "-j always" can be described as "crippling"; it would be nice to fix that, too, possibly by disabling LLVM-compilation under after startup completes.

Comment #1

Posted on Jun 25, 2009 by Helpful Elephant

(No comment was entered for this change.)

Comment #2

Posted on Jun 25, 2009 by Helpful Elephant

r675 improves the situation for normal_startup, but doesn't address startup_nosite:

trunk vs patch (default options; perf.py -r) normal_startup: Min: 0.435643 -> 0.319087: 36.53% faster Avg: 0.459272 -> 0.331541: 38.53% faster Significant (t=51.009351, a=0.95)

2009Q1 vs patch (default options; perf.py -r) normal_startup: Min: 0.381866 -> 0.317074: 20.43% faster Avg: 0.402331 -> 0.331774: 21.27% faster Significant (t=20.677263, a=0.95)

trunk vs patch (-O2 -j always; n=5) normal_startup: Min: 15.735776 -> 11.112612: 41.60% faster Avg: 15.795877 -> 11.144470: 41.74% faster Significant (t=151.105242, a=0.95)

Comment #3

Posted on Jun 27, 2009 by Helpful Elephant

r676 improves the situation further for normal_startup:

trunk vs patch normal_startup: Min: 0.320101 -> 0.284638: 12.46% faster Avg: 0.333535 -> 0.290565: 14.79% faster Significant (t=13.574358, a=0.95) Stddev: 0.03129 -> 0.00478: 553.99% smaller

2009Q1 vs patch normal_startup: Min: 0.380046 -> 0.284509: 33.58% faster Avg: 0.402265 -> 0.289813: 38.80% faster Significant (t=38.399910, a=0.95) Stddev: 0.02344 -> 0.01756: 33.47% smaller

trunk vs patch (-j always -O2; n=5) normal_startup: Min: 11.127711 -> 5.712456: 94.80% faster Avg: 11.146033 -> 5.722734: 94.77% faster Significant (t=923.701375, a=0.95) Stddev: 0.01110 -> 0.00701: 58.42% smaller

I'm moving the startup_nosite problem to Q3, now that normal_startup is faster.

Comment #4

Posted on Sep 29, 2009 by Helpful Elephant

(No comment was entered for this change.)

Comment #5

Posted on Jan 6, 2010 by Helpful Elephant

(No comment was entered for this change.)

Comment #6

Posted on Jan 14, 2010 by Helpful Elephant

Current status of startup time. These results are from installed versions of CPython 2.6.4 vs Unladen trunk (r988):

normal_startup

Min: 0.219186 -> 0.352075: 1.6063x slower Avg: 0.227228 -> 0.364384: 1.6036x slower Significant (t=-51.879098, a=0.95) Stddev: 0.00762 -> 0.02532: 3.3227x larger Timeline: http://tinyurl.com/yfe8z3r

startup_nosite

Min: 0.105949 -> 0.264912: 2.5004x slower Avg: 0.107574 -> 0.267505: 2.4867x slower Significant (t=-703.557403, a=0.95) Stddev: 0.00214 -> 0.00240: 1.1209x larger Timeline: http://tinyurl.com/yajn8fa

Note that if you run from the build directory, the results are different. This is due to the nature of the optimizations implemented in r676.

normal_startup

Min: 0.321331 -> 0.357681: 1.1131x slower Avg: 0.331351 -> 0.365976: 1.1045x slower Significant (t=-14.231352, a=0.95) Stddev: 0.00706 -> 0.02328: 3.2995x larger Timeline: http://tinyurl.com/yz6hlj4

startup_nosite

Min: 0.107814 -> 0.266355: 2.4705x slower Avg: 0.109281 -> 0.267502: 2.4478x slower Significant (t=-922.873066, a=0.95) Stddev: 0.00168 -> 0.00175: 1.0446x larger Timeline: http://tinyurl.com/yk9qj65

We need to optimize startup time again before final merger.

Comment #7

Posted on Jan 14, 2010 by Helpful Elephant

(No comment was entered for this change.)

Comment #8

Posted on Jan 21, 2010 by Helpful Elephant

r1019 added startup benchmarks based on Mercurial and Bazaar.

Comment #9

Posted on Jan 21, 2010 by Helpful Elephant

Further ideas that have come up recently (not mine): - Disable JIT compilation during startup, restore the Py_JitControl setting before entering user code. - Disable collection of runtime feedback data for cold functions using a multi-phase hotness model.

Comment #10

Posted on Jan 21, 2010 by Helpful Elephant

Comparing installed versions of CPython 2.6.4 vs Unladen Swallow r1024 using the new {hg,bzr}_startup benchmarks:

./perf.py -r -b hg_startup,bzr_startup /tmp/cpy26/bin/python /tmp/unladen/bin/python

bzr_startup

Min: 0.067990 -> 0.097985: 1.4412x slower Avg: 0.084322 -> 0.111348: 1.3205x slower Significant (t=-37.432534, a=0.95) Stddev: 0.00793 -> 0.00643: 1.2330x smaller Timeline: http://tinyurl.com/ybdm537

hg_startup

Min: 0.016997 -> 0.024997: 1.4707x slower Avg: 0.026990 -> 0.036772: 1.3625x slower Significant (t=-53.104502, a=0.95) Stddev: 0.00406 -> 0.00417: 1.0273x larger Timeline: http://tinyurl.com/ycout8m

Comment #11

Posted on Jan 22, 2010 by Helpful Elephant

Benchmarking r1027 with -j never against -j whenhot. This gauges the potential impact of the "disable JIT compilation during startup" idea:

./perf.py -r -b normal_startup --args ",-j never" /tmp/unladen/bin/python /tmp/unladen/bin/python

normal_startup

Min: 0.355344 -> 0.346220: 1.0264x faster Avg: 0.362940 -> 0.353413: 1.0270x faster Significant (t=4.751362, a=0.95) Stddev: 0.01925 -> 0.00560: 3.4367x smaller Timeline: http://tinyurl.com/yc24xqh

Comment #12

Posted on Jan 27, 2010 by Helpful Elephant

r1045 improves startup time slightly by disabling JIT compilation and feedback gathering during startup. Any two-phase hotness model needs to include this same effect: during startup, no feedback is collected. This patch is intended as a naive baseline to be improved upon.

$ ./perf.py -r -b startup ../a/python ../b/python

bzr_startup

Min: 0.091986 -> 0.089986: 1.0222x faster Avg: 0.106514 -> 0.104694: 1.0174x faster Significant (t=2.116822, a=0.95) Stddev: 0.00829 -> 0.00889: 1.0730x larger Timeline: http://tinyurl.com/yao44mw

hg_startup

Min: 0.025996 -> 0.022997: 1.1304x faster Avg: 0.037777 -> 0.036090: 1.0468x faster Significant (t=9.174211, a=0.95) Stddev: 0.00420 -> 0.00403: 1.0420x smaller Timeline: http://tinyurl.com/yc7f6cc

normal_startup

Min: 0.344597 -> 0.330059: 1.0440x faster Avg: 0.358112 -> 0.343796: 1.0416x faster Significant (t=3.619648, a=0.95) Stddev: 0.01967 -> 0.03432: 1.7449x larger Timeline: http://tinyurl.com/ykkkl2d

startup_nosite

Min: 0.250642 -> 0.246434: 1.0171x faster Avg: 0.252985 -> 0.248573: 1.0178x faster Significant (t=20.164605, a=0.95) Stddev: 0.00233 -> 0.00204: 1.1397x smaller Timeline: http://tinyurl.com/ybyj8px

Status: Accepted

Labels:
Type-Defect Priority-High Performance Release-Merger