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 Sun, 10 Dec 2006 01:09:51 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.

Well, actually the analysis that I've done is not very fresh. This code 
I've written in the end of September but didn't make a comparison with 
Sun. Back then the numbers were smaller, it used to be "just" ~195k 
method calls in LIVE phase, and java/io/ByteArrayOutputStream;.write(I)V 
method was called "only" 93k times.

The number of Java methods which are executed just for system class 
loader to find a user class grew since that time in 1.5 times. Maybe it 
happened in the last 2 weeks.

> 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 

Done.

> site?  I'm going to make a little JVMTI "how to" and that's a cute bit 
> of code to use as an example.

If you have any questions, I'd really like to help with this.

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


-- 
Gregory


Mime
View raw message