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, 24 Dec 2006 20:45:55 GMT
On Sunday 24 December 2006 23:01 Gregory Shimansky wrote:
> On Saturday 23 December 2006 20:48 Mikhail Loenko wrote:
> > Can you publish most common stacks for the
> > "157114 Ljava/io/ByteArrayOutputStream;.write(I)V"
>
> Yes I've been going to do this for some time already and now that you've
> asked, I have finally written a modified agent version which can monitor a
> method which is specified on the command line. The agent code is available
> at [1] (run like
> this:
> -agentlib:methodee-stack='Ljava/io/ByteArrayOutputStream;.write(I)V').
>
> After the log is generated it can be parsed with the following script
>
> cat method_stack.log | sort | uniq -c | sort -nr | sed -e 's/ /\n/g'
>
> I've found that Ljava/io/ByteArrayOutputStream;.write(I)V is used only in 9
> different stacks when running hello world. The most popular stack trace
> which is used 147319 times looks like this:

To make things clear, in the following stack trace the numbers at line ends 
are not source line numbers. These are java bytecode numbers inside of the 
method.

> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List
>;) [B:310
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Att
>ributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:373
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:20
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:45
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:92
> Ljava/net/URLClassLoader;.explore(Ljava/net/URL;I)[Ljava/net/URL;:475
> Ljava/net/URLClassLoader;.findClassImpl([Ljava/net/URL;Ljava/lang/String;)L
>java/lang/Class;:897 Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:14
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:0
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/Privileged
>Action;Ljava/security/AccessControlContext;)Ljava/lang/Object;:82
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedActi
>on;Ljava/security/AccessControlContext;)Ljava/lang/Object;:15
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:12
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:49
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Lja
>va/lang/Class;:64
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:2
>
> The rest 8 different stack traces differ only after
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:20 line. The top 2
> methods are called from different locations of
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Att
>ributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V and
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List
>;) [B. I am afraid the manifest parsing code has to be changed to improve
> its performance.
>
> [1] http://people.apache.org/~gshimansky/methodee-stack.cpp
>
> > 2006/12/23, Gregory Shimansky <gshimansky@gmail.com>:
> > > On Saturday 23 December 2006 04:09 Stefano Mazzocchi wrote:
> > > > Gregory Shimansky wrote:
> > > > > 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
> > > > >/O bjec t;II)V 6300
> > > > > Ljava/lang/System;.arraycopy(Ljava/lang/Object;ILjava/lang/Object;I
> > > > >I) V 6248 Ljava/lang/String;.length()I
> > > > >    6130 Ljava/lang/String;.substring(II)Ljava/lang/String;
> > > > >
> > > > > We seem to copy memory really too much...
> > > >
> > > > Not sure I get these results: assuming a "hello world" application
> > > > reads only, why is 80% of the time spent writing?
> > >
> > > Most of the executed code in the table is what it takes for the system
> > > java class loader to find and load hello world application class. I
> > > think many of those java.io.ByteArrayOutputStream.write calls are used
> > > in JAR files manifest parser which writes to memory byte by byte. Maybe
> > > there are other places too.
> > >
> > > --
> > > Gregory

-- 
Gregory

Mime
View raw message