harmony-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From Stefano Mazzocchi <stef...@apache.org>
Subject Re: [drlvm] things feel slow...
Date Sun, 10 Dec 2006 00:54:36 GMT
Geir Magnusson Jr. wrote:
> This is great stuff, but I meant "relative to a week or so ago".  IOW,
> it feels like we slowed down recently.
> 
> That said, what you have below is great, and certainly will be good
> fodder for someone to look into.  We should capture it as a ToDo.
> 
> Could you please put an Apache license on the top of the code on your
> site?  I'm going to make a little JVMTI "how to" and that's a cute bit
> of code to use as an example.

Yes!!

> 
> geir
> 
> 
> Gregory Shimansky wrote:
>> 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 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
>>


-- 
Stefano.


Mime
View raw message