Re: [Jython-users] jython-2.1b1 startup time

[Jan Wender]
>I removed the cachedir and started each jython version two times, and there are
>large differences between the first and second startup and not so large between
>2.1a3 and 2.1b1.
Thanks. Now I'm convinced that the jar cache isn't the problem in your
case.
Then try something like this. Notice the -S option.
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import site; print time() - t"
0.11000001430511475
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import site; print time() - t"
0.44099998474121094
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import re; print time() - t"
0.24000000953674316
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import re; print time() - t"
0.25099992752075195
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import os; os.sep; print time() - t"
0.04999995231628418
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import os; os.sep; print time() - t"
0.3500000238418579
I use time.time() to do the timing, but that might only make sense for
win2k. Keep using the shell time command for *nix. Make sure you run
each command a couple of times to avoid disk cache artifacts.
The slowdown that I can measure is consistent with the use of "re" in
"os".
>Would it help if I tried different Java VMs?
Let's stick with what we have for now.
>I hope this helps, I really want to find the cause of this slowdown.
Me too.
regards,
finn

Thread view

Hi,
I note a big difference in startup time between
Jython-2.1a3 and Jython-2.1b1 (using the same JVM
and same registry).
Executing the following script (exit.py):
import sys
sys.exit(0)
I got these times:
$ time /opt/jython-2.1a3/jython exit.py
real 0m0.830s
user 0m0.760s
sys 0m0.040s
$ time /opt/jython-2.1b1/jython exit.py
real 0m5.577s
user 0m5.490s
sys 0m0.070s
Does anyone else note a similar difference?
Is it special to Jython-2.1b ?
--Stefan

[Stefan]
>Hi,
>
>I note a big difference in startup time between
>Jython-2.1a3 and Jython-2.1b1 (using the same JVM
>and same registry).
Which JVM?
>Executing the following script (exit.py):
>
>import sys
>sys.exit(0)
>
>I got these times:
>
>$ time /opt/jython-2.1a3/jython exit.py
>
>real 0m0.830s
>user 0m0.760s
>sys 0m0.040s
>
>
>$ time /opt/jython-2.1b1/jython exit.py
>
>real 0m5.577s
>user 0m5.490s
>sys 0m0.070s
>
>Does anyone else note a similar difference?
>Is it special to Jython-2.1b ?
Is that 5 seconds real time? No, I certainly does not see that on win2k
using javasoft JVMs.
Maybe its scanning CLASSPATH jar files. Do you have write access to the
"cachedir" directory?
If your JVM have some kind of verbose options, try running with
different kind of verbosity enabled. Maybe it will give some clues about
what it is doing in that time.
regards,
finn

[Jan Wender on slow startup for 2.1b1]
>I also noticed it on Unix systems:
>Linux (MSC.2001Aug on i686)
>
>ian@... tmp > time jython -c 'import sys; sys.exit()'
>
>real 0m4.859s
>user 0m3.370s
>sys 0m0.100s
>ian@... tmp > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()'
>
>real 0m1.964s
>user 0m1.740s
>sys 0m0.090s
>
>DEC Alpha OSF1 alpha V4.0
>ian@... 200gui > time jython -c 'import sys; sys.exit()'
>
>real 0m10.416s
>user 0m9.703s
>sys 0m0.383s
>ian@... 200gui > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()'
>
>real 0m2.498s
>user 0m2.072s
>sys 0m0.313s
>
>> Which JVM?
>Linux:
>ian@... tmp > java -version
>java version "1.3.1_01"
>Java(TM) 2 Runtime Environment, Standard Edition (build 1.3.1_01)
>Java HotSpot(TM) Client VM (build 1.3.1_01, mixed mode)
>
>Alpha:
>ian@... 200gui > java -version
>java version "1.3.0"
>Java(TM) 2 Runtime Environment, Standard Edition
>Classic VM (build 1.3.0-1, native threads, jit)
>
>
>> Maybe its scanning CLASSPATH jar files. Do you have write access to the
>> "cachedir" directory?
>
>Yes, and it has not scanned the jar files, because I called it twice and =
>took only the second timing.
I'm sure it have scanned the jar files. The question is whether jython
wrote the scan result info cachedir/packages. Is the cachedir/packages
directory empty or non-existing?
The problem was fixed in Stefan's case by running a chmod on the files
and subdirectories in cachedir.
>>
>> If your JVM have some kind of verbose options, try running with
>> different kind of verbosity enabled. Maybe it will give some clues about
>> what it is doing in that time.
>I have attached two logfiles, produced with=20
>scjava -verbose -Dpython.home=3D"/home/ian/jython-2.1a3" -classpath "/hom=
>e/ian/jython-2.1a3/jython.jar:$CLASSPATH" "org.python.util.jython" >loga3
>resp.
>scjava -verbose -Dpython.home=3D"/usr/local/jython-2.1b1" -classpath "/us=
>r/local/jython-2.1b1/jython.jar:$CLASSPATH" "org.python.util.jython" >log=
>b1
>
>CLASSPATH is /home/ian/venus/200gui/gui/jar/xmlrpc-a.jar in both cases.
>
>The b1 loads a lot (36) more libraries than the a3, this is probably causing
>the delay.
The vast majority of the additional classes is the "sre" module. This is
now loaded by the "os" module which is loaded by the "site.py" file.
We might have to rethink the use of re's in javaos.py, but for now I
have a very hard time believing that we can measure the overhead of an
additional 36 classes with a stopwatch.
The prime suspect is still the lack of caching of the jar scan result.
Try to remove cachedir just to verify that the startup time become
significantly larger.
regards,
finn

[Jan Wender]
>I removed the cachedir and started each jython version two times, and there are
>large differences between the first and second startup and not so large between
>2.1a3 and 2.1b1.
Thanks. Now I'm convinced that the jar cache isn't the problem in your
case.
Then try something like this. Notice the -S option.
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import site; print time() - t"
0.11000001430511475
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import site; print time() - t"
0.44099998474121094
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import re; print time() - t"
0.24000000953674316
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import re; print time() - t"
0.25099992752075195
>jython-2.1a3-jdk13\jython -S -c "from time import time; t = time(); import os; os.sep; print time() - t"
0.04999995231628418
>jython-2.1b1-jdk13\jython -S -c "from time import time; t = time(); import os; os.sep; print time() - t"
0.3500000238418579
I use time.time() to do the timing, but that might only make sense for
win2k. Keep using the shell time command for *nix. Make sure you run
each command a couple of times to avoid disk cache artifacts.
The slowdown that I can measure is consistent with the use of "re" in
"os".
>Would it help if I tried different Java VMs?
Let's stick with what we have for now.
>I hope this helps, I really want to find the cause of this slowdown.
Me too.
regards,
finn

On Wed, Dec 12, 2001 at 03:38:22PM +0000, Finn Bock wrote:
> Hmm. Maybe it isn't using the compiled $py.class files for the sre
> modules. Make sure that jython has created $py.class files for the sre
> modules.
Bingo! For the 2.1b1 version I moved the jython directory from my home to
/usr/local, which is not writable for normal users.
So the .py$class-files never got written.
Giving myself write access on the Lib directory results in:
ian@... > jython -S -c "from time import time; t =3D time(); import re; p=
rint time() - t"
0.6260000467300415
which is the same as for the 2.1a3 version.
Thanks for your time and sorry for producing so much trouble!
Cheerio,
--=20
J.Wender@... - Fon +4970719457-257 Fax-211
science+computing ag - Hagellocher Weg 71-75 - 72070 T=FCbingen
Nobody writes jokes in base 13. (Douglas Adams)