From: Stefan <sd...@or...> - 2001-12-10 10:19:04
|
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 |
From: <bc...@wo...> - 2001-12-10 21:12:57
|
[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 |
From: Jan W. <j.w...@sc...> - 2001-12-11 14:07:21
|
On Mon, Dec 10, 2001 at 09:16:25PM +0000, Finn Bock wrote: > [Stefan] >=20 > >Hi, > > > >I note a big difference in startup time between > >Jython-2.1a3 and Jython-2.1b1 (using the same JVM > >and same registry). I also noticed it on Unix systems: Linux (MSC.2001Aug on i686) ian@leo tmp > time jython -c 'import sys; sys.exit()' real 0m4.859s user 0m3.370s sys 0m0.100s ian@leo 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@alpha 200gui > time jython -c 'import sys; sys.exit()' real 0m10.416s user 0m9.703s sys 0m0.383s ian@alpha 200gui > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' real 0m2.498s user 0m2.072s sys 0m0.313s >=20 > Which JVM? Linux: ian@leo 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@alpha 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. >=20 > If your JVM have some kind of verbose options, try running with > different kind of verbosity enabled. Maybe it will give some clues abou= t > 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 caus= ing the delay. Cheerio, --=20 J.W...@sc... - Fon +4970719457-257 Fax-211 science+computing ag - Hagellocher Weg 71-75 - 72070 T=FCbingen The man who letterspaces lowercase letters also steals sheep. (F. Goudy) |
From: <bc...@wo...> - 2001-12-11 20:24:46
|
[Jan Wender on slow startup for 2.1b1] >I also noticed it on Unix systems: >Linux (MSC.2001Aug on i686) > >ian@leo tmp > time jython -c 'import sys; sys.exit()' > >real 0m4.859s >user 0m3.370s >sys 0m0.100s >ian@leo 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@alpha 200gui > time jython -c 'import sys; sys.exit()' > >real 0m10.416s >user 0m9.703s >sys 0m0.383s >ian@alpha 200gui > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' > >real 0m2.498s >user 0m2.072s >sys 0m0.313s > >> Which JVM? >Linux: >ian@leo 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@alpha 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 |
From: Jan W. <j.w...@sc...> - 2001-12-12 07:34:01
|
On Tue, Dec 11, 2001 at 08:28:24PM +0000, Finn Bock wrote: >=20 > 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? In ~/.jython: python.cachedir=3D/home/ian/.jython-cachedir ian@leo > ls -ld /home/ian/.jython-cachedir drwxr-xr-x 3 ian s+c 21 Dec 4 15:24 /home/ian/.jython= -cachedir/=20 ian@leo jsse1.0.2 > ls -ld /home/ian/.jython-cachedir/packages=20 drwxr-xr-x 2 ian s+c 4096 Dec 11 14:55 /home/ian/.jython= -cachedir/packages/ So it should be existing and writable. In the packages directory there ar= e the files: ian@leo > ls /home/ian/.jython-cachedir/packages ant.pkc gl4java.pkc i18n.pkc jython$2.pkc optional.pkc rt$1.pkc sunrsasig= n$1.pkc xmlrpc-a$1.pkc crimson.pkc i18n$1.pkc jaxp.pkc jython$3.pkc packages.idx rt$2.pkc sunrsasign$2.pkc xmlrpc-a.pkc gl4java-glutfonts.pkc i18n$2.pkc jython$1.pkc jython.pkc png.pkc rt.pkc sunrsasign.pkc , all -rw-r--r--, owner ian. >=20 > The problem was fixed in Stefan's case by running a chmod on the files > and subdirectories in cachedir. >=20 > 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. I removed the cachedir and started each jython version two times, and the= re are large differences between the first and second startup and not so large b= etween 2.1a3 and 2.1b1. Would it help if I tried different Java VMs? Although IBM Java gives a SI= GSEGV and must be killed -9, with both jython versions. ian@leo > rm -rf ~/.jython-cachedir/packages ian@leo > time jython -c 'import sys; sys.exit()' *sys-package-mgr*: processing new jar, '/usr/local/jython-2.1b1/jython.ja= r' *sys-package-mgr*: processing new jar, '/home/ian/venus/200gui/gui/jar/xm= lrpc-a.jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/rt.= jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/i18= n.jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/sun= rsasign.jar' real 0m10.758s user 0m8.370s sys 0m0.300s ian@leo > time jython -c 'import sys; sys.exit()' real 0m4.886s user 0m3.440s sys 0m0.110s ian@leo > rm -rf ~/.jython-cachedir/packages ian@leo > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' *sys-package-mgr*: processing new jar, '/home/ian/jython-2.1a3/jython.jar= ' *sys-package-mgr*: processing new jar, '/home/ian/venus/200gui/gui/jar/xm= lrpc-a.jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/rt.= jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/i18= n.jar' *sys-package-mgr*: processing new jar, '/usr/java/jdk1.3.1_01/jre/lib/sun= rsasign.jar' real 0m7.062s user 0m6.530s sys 0m0.180s ian@leo > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' real 0m1.878s user 0m1.610s sys 0m0.120s ian@alpha > rm -rf ~/.jython-cachedir/packages ian@alpha > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' *sys-package-mgr*: processing new jar, '/net/leo/home/ian/jython-2.1a3/jy= thon.jar' *sys-package-mgr*: processing new jar, '/net/leo/home/ian/venus/200gui/gu= i/jar/xmlrpc-a.jar' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/rt.jar' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/i18n.jar= ' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/sunrsasi= gn.jar' real 0m30.020s user 0m28.047s sys 0m0.850s ian@alpha > time ~/jython-2.1a3/jython -c 'import sys; sys.exit()' real 0m2.595s user 0m2.167s sys 0m0.298s ian@alpha > rm -rf ~/.jython-cachedir/packages ian@alpha > time jython -c 'import sys; sys.exit()' *sys-package-mgr*: processing new jar, '/usr/local/jython-2.1b1/jython.ja= r' *sys-package-mgr*: processing new jar, '/net/leo/home/ian/venus/200gui/gu= i/jar/xmlrpc-a.jar' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/rt.jar' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/i18n.jar= ' *sys-package-mgr*: processing new jar, '/usr/opt/java130/jre/lib/sunrsasi= gn.jar' real 0m36.303s user 0m33.973s sys 0m0.935s ian@alpha > time jython -c 'import sys; sys.exit()' real 0m11.431s user 0m10.519s sys 0m0.428s I hope this helps, I really want to find the cause of this slowdown. Cheerio, --=20 J.W...@sc... - Fon +4970719457-257 Fax-211 science+computing ag - Hagellocher Weg 71-75 - 72070 T=FCbingen Lisp is truly amazing. Anything that's cool in any language existed in L= isp before, and probably is still more usable in Lisp. (W. Tanksley in c.l.py= thon) |
From: <bc...@wo...> - 2001-12-12 10:31:08
|
[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 |
From: Jan W. <j.w...@sc...> - 2001-12-12 16:13:42
|
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@leo > 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.W...@sc... - Fon +4970719457-257 Fax-211 science+computing ag - Hagellocher Weg 71-75 - 72070 T=FCbingen Nobody writes jokes in base 13. (Douglas Adams) |