Geir Magnusson Jr. wrote:
The DRLVM suite...
So the question is... was 20-25 min the time you expected?
Mikhail Loenko wrote:
which tests did you run?
I ran Classlib tests on DRLVM in "once" fork mode. it took about 20-25
minutes
on each x86 and x86_64 on Linux
2006/12/9, Geir Magnusson Jr. <[EMAIL PROTECTED]>:
I've been running tests on x86 and x86_64 linux, and things "feel" slow.
Problem is I don't have any times to compare to - can we add that to
the data recorded in harmonytest?
Does anyone else feel that things are slow?
I think the worst place in executing tests in "once" mode is
initialization stage of VM + classlib. I've written a simple JVMTI agent
which uses JVMTI MethodEntry event [1] just to count called classlib
methods to execute a Hello world program. The program itself is very
small, so almost all of the called methods are classlib initialization.
Also keep in mind that MethodEntry event is sent only in LIVE [2] JVMTI
phase, this means that classlib bootstrap, and classlib shutdown are not
included.
After agent is executed, it creates a log of called methods. The number
of methods which I get is 345718. This is very very many. Comparing with
Sun JRE, the number of methods they use is 9482. True that when drlvm
runs in JVMTI mode, it uses only Jitrino.JET, which doesn't inline any
methods, but on the other hand Sun when running in JVMTI mode should
report every called method as well. So the difference with Sun is 36
times. Agent code is in [3]. On windows compile like this:
cl
-Ic:/work/harmony/enhanced/trunk/working_vm/build/win_ia32_msvc_debug/deploy/jre/include
-Femethodee.dll -LD methodee.cpp
execute like this:
java -agentpath:methodee.dll Hello
To count methods which agent doesn't see in classlib bootstrap and
shutdown phases I've created a small patch which adds tracing to drlvm
to jvmti_method_enter_callback. This function is always called when
JVMTI registers can_generate_method_entry_events capability. The calls
to agent are filtered out when phase is not LIVE. Using this patch I get
all of the methods which are executed. The number in this case is
356826. So this gives only 11108 calls in bootstrap and shutdown. The
number is not very big compared to what is executed in LIVE phase. Patch
code is in [4]. Add
-Xtrace:jvmti.event.method.entry:log.txt
to the above command line to log tracing to file when running drlvm).
It seems like 99% of all LIVE phase calls are user class loader
execution. All of those 345k calls are what it takes for Java class
loader to find Hello world class. Analyzing the log with this script
cat method_entry.log | sort | uniq -c | sort -nr
I've found the top 10 methods which are executed most of the times:
156382 Ljava/io/ByteArrayOutputStream;.write(I)V
19985 Ljava/lang/Object;.<init>()V
13927 Ljava/lang/String;.hashCode()I
9259 Ljava/lang/Character;.toLowerCase(C)C
7807 Ljava/io/ByteArrayOutputStream;.size()I
7648 Ljava/lang/String;.<init>(II[C)V
6299
Ljava/lang/System;.arraycopy(Ljava/lang/Object;ILjava/lang/Object;II)V
6219 Ljava/lang/String;.length()I
6101 Ljava/lang/String;.substring(II)Ljava/lang/String;
6089 Ljava/util/ArrayList;.size()I
the first one is absolute champion. I wonder why it is used to many
times. It looks like some parts of classlib copy memory byte by byte
extensively using ByteArrayOutputStream. It is probably a good starting
place for performance improvement.
[1] http://java.sun.com/j2se/1.5.0/docs/guide/jvmti/jvmti.html#MethodEntry
[2] http://java.sun.com/j2se/1.5.0/docs/guide/jvmti/jvmti.html#GetPhase
[3] http://people.apache.org/~gshimansky/methodee.cpp
[4] http://people.apache.org/~gshimansky/jvmti.patch
--
Gregory
