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 Fri, 22 Dec 2006 21:03:26 GMT
I was not aware that drlvm didn't generate MethodEnter/Exit events for native 
methods when I wrote this email. Now after applying HARMONY-2828 which fills 
this gap I've rerun my test agent and the top10 for most called methods to 
run hello world application has changed. The new top10 list looks like this:

 157114 Ljava/io/ByteArrayOutputStream;.write(I)V
  20093 Ljava/lang/Object;.<init>()V
  13975 Ljava/lang/String;.hashCode()I
   9301 Ljava/lang/Character;.toLowerCase(C)C
   7842 Ljava/io/ByteArrayOutputStream;.size()I
   7692 Ljava/lang/String;.<init>(II[C)V
   6300 
Ljava/lang/VMMemoryManager;.arrayCopy(Ljava/lang/Object;ILjava/lang/Object;II)V
   6300 Ljava/lang/System;.arraycopy(Ljava/lang/Object;ILjava/lang/Object;II)V
   6248 Ljava/lang/String;.length()I
   6130 Ljava/lang/String;.substring(II)Ljava/lang/String;

We seem to copy memory really too much...

On Sunday 10 December 2006 01:35 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/deplo
>y/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