harmony-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Gregory Shimansky <gshiman...@gmail.com>
Subject Re: [drlvm] things feel slow...
Date Sat, 09 Dec 2006 22:35:46 GMT
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. <geir@pobox.com>:
>>> 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 

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:

-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


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
    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


View raw message