You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@harmony.apache.org by "Gregory Shimansky (JIRA)" <ji...@apache.org> on 2007/07/30 17:15:53 UTC
[jira] Created: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
[classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
-------------------------------------------------------------------------------------------------
Key: HARMONY-4569
URL: https://issues.apache.org/jira/browse/HARMONY-4569
Project: Harmony
Issue Type: Bug
Components: Classlib
Reporter: Gregory Shimansky
I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
Parsing the logs for statistics can be done with the following command:
cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
Ljava/io/ByteArrayOutputStream;.write(I)V:0
Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
Ljava/net/URLClassLoader;.makeNewHandler()V:64
Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
[1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
[2] http://people.apache.org/~gshimansky/methodee.cpp
[3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12585062#action_12585062 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Sorted method call quantities for Hello, World:
13589 Ljava/lang/Object;.<init>()V
8220 Ljava/nio/ReadWriteHeapByteBuffer;.protectedArrayOffset()I
8220 Ljava/nio/ByteBuffer;.arrayOffset()I
8157 Ljava/nio/Buffer;.position()I
8087 Ljava/nio/ReadWriteCharArrayBuffer;.protectedArrayOffset()I
8087 Ljava/nio/CharBuffer;.arrayOffset()I
5653 Ljava/nio/Buffer;.remaining()I
5544 Ljava/nio/Buffer;.position(I)Ljava/nio/Buffer;
5384 Ljava/nio/ReadWriteCharArrayBuffer;.protectedArray()[C
5384 Ljava/nio/CharBuffer;.array()[C
[...]
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Closed: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Gregory Shimansky (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gregory Shimansky closed HARMONY-4569.
--------------------------------------
Ok I see from your explanation that performance problems now exist in different area, not in manifest parser. Thank you for fixing this bug. I think it is about time we close it, it has by far too much comments to understand.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583353#action_12583353 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Nathan,
I'm sorry for writing something that looks like an insult. Why should I do that? English is not my native language, I do not talk English and possess only strange writing patterns from scientific papers. For example, I was checking the meaning of the word "conventional" in the dictionary before writing the previous comment. I'm sorry for things which sound strange. I'm ok to continue on the dev list, but please do not take anything personally.
> Even though you may not like it, it doesn't make it a bug, incorrect, inappropriate or bad.
This mostly answers my question. I see that someone else doesn't think that numeric entries are not bad. I have a reasoning why symbolic entries are better. Consider two variants:
1. numeric entry without a comment vs symbolic entry
the latter is understandable, while the former requires me to check the source file
2. numeric entry with an explanatory comment vs symbolic entry
The symbolic entry is more compact, and hence, more readable
Finally, my motivation is not to prove that some notation is better then another. I'm just trying to figure out the current state of things. While I may be able to answer you something about VM design which might be more complex than localization conventions, this does not mean that I'm able to reverse engineer these conventions accepted in community of Harmony Java developers just by looking through archive.00 - archive.ff.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Pavel Pervov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12585076#action_12585076 ]
Pavel Pervov commented on HARMONY-4569:
---------------------------------------
AFAIU hotspots are measured by time spent, not by number of calls.Is it possible to profile HWA with e.g. TPTP?
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12585108#action_12585108 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Yes, the time is important.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583335#action_12583335 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
> That's unbelievable.
Committing big patches is usually very painful.
> Because we don't all go off inventing our own idea of how the code should be designed. You may disagree with the use of unreadable identifiers,
> and if so you should suggest they are changed throughout. Having the mixture of styles makes the code less understandable IMO.
I accept this. From the other side there might be some rationale (convention or a tool) which explains why the numbers are used instead of human readable form. This does not look a legacy since luni package uses different convention, though unreadable as well.
I question your change just because I want to understand these conventions.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Nathan Beyer (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583342#action_12583342 ]
Nathan Beyer commented on HARMONY-4569:
---------------------------------------
Convention is what exists in the code today. The naming convention of the localization keys should be fairly obvious from looking at the messages file and the source that uses those keys.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12586121#action_12586121 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Eclipse scenario statistics (actually tried to reproduce a bug against object tracing)
5500379 Ljava/lang/String;.charAt(I)C
4505554 Ljava/lang/Object;.<init>()V
3968891 Ljava/lang/String;.equals(Ljava/lang/Object;)Z
3379700 Ljava/lang/AbstractStringBuilder;.append0(C)V
3328274 Ljava/lang/StringBuffer;.append(C)Ljava/lang/StringBuffer;
3270757 Ljava/lang/VMMemoryManager;.arrayCopy(Ljava/lang/Object;ILjava/lang/Object;II)V
3270757 Ljava/lang/System;.arraycopy(Ljava/lang/Object;ILjava/lang/Object;II)V
2549856 Ljava/lang/String;.compareTo(Ljava/lang/String;)I
2237272 Ljava/lang/String;.hashCode()I
1994959 Ljava/lang/String;.length()I
1726158 Ljava/lang/String;.regionMatches(ILjava/lang/String;II)Z
1546970 Ljava/lang/String;.indexOf(II)I
1172805 Ljava/util/HashMap;.findNonNullKeyEntry(Ljava/lang/Object;II)Ljava/util/HashMap$Entry;
1055439 Lorg/eclipse/core/runtime/Path;.segment(I)Ljava/lang/String;
1030393 Lorg/eclipse/core/internal/dtree/AbstractDataTreeNode;.indexOfChild(Ljava/lang/String;)I
1016667 Ljava/lang/String;.<init>([CII)V
1010311 Ljava/lang/String;.<init>(II[C)V
935070 Lorg/eclipse/core/internal/dtree/AbstractDataTreeNode;.childAtOrNull(Ljava/lang/String;)Lorg/eclipse/core/internal/dtree/AbstractDataTreeNode;
915081 Lorg/apache/xerces/util/XMLChar;.isContent(I)Z
898176 Lorg/eclipse/osgi/framework/util/KeyedHashSet$EquinoxSetIterator;.hasNext()Z
897999 Ljava/util/HashMap;.getEntry(Ljava/lang/Object;)Ljava/util/HashMap$Entry;
892240 Ljava/lang/Character;.isWhitespace(C)Z
856714 Ljava/util/HashMap;.get(Ljava/lang/Object;)Ljava/lang/Object;
836404 Ljava/io/BufferedOutputStream;.write(I)V
826789 Lorg/eclipse/core/internal/dtree/AbstractDataTreeNode;.isDelta()Z
770999 Lcom/ibm/icu/impl/CharTrie;.getCodePointValue(I)C
730354 Ljava/lang/Object;.equals(Ljava/lang/Object;)Z
722554 Lorg/eclipse/core/internal/localstore/SafeFileOutputStream;.write(I)V
710578 Lorg/eclipse/jdt/internal/ui/text/spelling/engine/DefaultPhoneticHashProvider;.hasOneOf([Ljava/lang/String;[CII)Z
706964 Ljava/lang/String;.getChars(II[CI)V
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Tim Ellison (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12582986#action_12582986 ]
Tim Ellison commented on HARMONY-4569:
--------------------------------------
Alexei, please take a look and see if this has caused HARMONY-5662.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12575493#action_12575493 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
With a confidence level of 0.99 the patch gives 3.25% +/- 0.02 speed up on Eclipse startup.
M5 Patch Diff
19.64 19.89 -0.25
20.75 17.04 3.71
18.82 16.79 2.03
16.53 16.71 -0.18
18.47 19.1 -0.63
19.34 19.12 0.22
19.41 16.56 2.85
19.46 18.36 1.1
19.52 18.28 1.24
18.76 15.22 3.54
17.88 18.12 -0.24
19.97 17.45 2.52
17.24 16.89 0.35
17.14 17.67 -0.53
19.05 18.67 0.38
17.3 17.46 -0.16
18.52 20.17 -1.65
17.24 18.1 -0.86
20.29 17.51 2.78
18.07 16.85 1.22
19.42 19.5 -0.08
19.3 15.77 3.53
18.83 19.15 -0.32
20.61 19.27 1.34
19.02 18.58 0.44
19.08 17.59 1.49
15.37 19.05 -3.68
18.64 17.05 1.59
16.35 18.8 -2.45
17.87 17.51 0.36
17.36 19.23 -1.87
18.34 16.66 1.68
19.2 17.65 1.55
18.15 19.53 -1.38
19.16 17.7 1.46
16.62 16.89 -0.27
16.1 18.34 -2.24
18.72 17.32 1.4
17.03 19.12 -2.09
17.68 18.03 -0.35
19.39 15.85 3.54
17.04 17.82 -0.78
17.54 15.98 1.56
16.95 19.87 -2.92
17.03 18.62 -1.59
17.42 17.31 0.11
17.85 19.78 -1.93
18.28 18.62 -0.34
19.46 16.85 2.61
18.23 18.65 -0.42
16.96 16.87 0.09
17.53 19.5 -1.97
18.51 18.14 0.37
17.89 16.82 1.07
16.56 15.85 0.71
17.03 17.2 -0.17
17.98 17.81 0.17
19.13 18 1.13
18.22 19.1 -0.88
19.48 16.56 2.92
19.89 19.81 0.08
20.04 17.78 2.26
19.61 18.33 1.28
15.86 16.75 -0.89
17.19 17.1 0.09
17.65 17.48 0.17
20.9 18.53 2.37
19 18.58 0.42
18.46 16.85 1.61
16.19 17.82 -1.63
17.89 19.28 -1.39
18.83 17.42 1.41
18.87 17.07 1.8
17.17 17.59 -0.42
17.1 17.92 -0.82
18.66 18.78 -0.12
20.6 18.71 1.89
21.12 18.68 2.44
17.97 19.03 -1.06
16.29 16.12 0.17
17.18 16.71 0.47
18.05 17.87 0.18
20.37 18.79 1.58
17.09 16.96 0.13
18.17 18.55 -0.38
18.75 18.03 0.72
18.2 16.9 1.3
17.54 20.13 -2.59
18.35 17.42 0.93
18.23 16.32 1.91
19.77 19.2 0.57
15.97 18.29 -2.32
19.65 18.79 0.86
19.26 17.67 1.59
17.02 18.4 -1.38
19.03 17.86 1.17
17.48 16.55 0.93
17.87 17.23 0.64
19.62 17.58 2.04
16.52 15.74 0.78
18.59 19 -0.41
20.87 19.23 1.64
19.81 16.49 3.32
17.58 17.65 -0.07
16.81 19.02 -2.21
17.13 17.97 -0.84
18.7 19.33 -0.63
19.31 18.89 0.42
19.78 19.75 0.03
17.48 19.51 -2.03
19.27 15.48 3.79
20.07 18.14 1.93
15.19 18.68 -3.49
18.82 17.89 0.93
16.96 15.73 1.23
19.38 15.51 3.87
18.76 17.6 1.16
19 16.28 2.72
18 19.86 -1.86
18.7 16.04 2.66
19.02 15.24 3.78
16.32 16.41 -0.09
20.38 17.99 2.39
16.63 18.62 -1.99
20.08 18.44 1.64
18.62 17.45 1.17
19.79 16.16 3.63
17.49 17.57 -0.08
18.14 18.79 -0.65
18.7 16.57 2.13
18.6 17.64 0.96
18.3 16.78 1.52
17.53 18.34 -0.81
18.44 18.52 -0.08
18.78 18.39 0.39
19.77 16.26 3.51
18.34 17.86 0.48
17.53 16.91 0.62
19.11 17.05 2.06
18.99 16.48 2.51
19.15 19.34 -0.19
17.89 17.56 0.33
17.64 15.03 2.61
16.19 18.47 -2.28
18.26 20.9 -2.64
15.62 19.11 -3.49
18.89 17.78 1.11
19.66 17.79 1.87
16.55 17.6 -1.05
18.94 19.54 -0.6
16.12 16.54 -0.42
16.8 17.76 -0.96
17.81 19.1 -1.29
17 17.95 -0.95
19.51 16.5 3.01
21.44 17.49 3.95
17.71 17.67 0.04
18.63 16.67 1.96
20.56 18.24 2.32
18.23 18.56 -0.33
19.37 18.23 1.14
21.4 18.06 3.34
20.51 18.84 1.67
20.26 17.15 3.11
17.94 18.53 -0.59
19.07 16.9 2.17
18.38 14.87 3.51
19.12 17.5 1.62
21.96 17.75 4.21
20.04 16.12 3.92
19.34 18.89 0.45
AVG 0.598947368
STDEV 1.727457858
Confidence level 0.01
Count 171
Student 2.605058344
Delta 0.344133428
AVG M5 18.41461988
AVG, % 3.25%
Delta, % 0.018688055
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_todo.patch
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12584094#action_12584094 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Gregory,
Sorry, I have missed your comment. You are correct. Initially I've inlined UTF-8 decoding into sources [1]. Then I decided to avoid duplicating code and started using our decoder. Currently we are facing problems in the implementation of our decoder [2]. I have mostly fixed it but believe that it worth to file another bug: it is a bit crowded here.
Thank you for discovering an excellent testing method.
[1] My hand-made decoder:
if (utf8Progress == 0) {
if (next < 128) {
c = (char) next;
} else if ((next & 0xe0) == 0xc0) {
utf8Progress = 1;
c = (char) ((next & 0x1F) << 6);
} else if ((next & 0xf0) == 0xe0) {
utf8Progress = 2;
c = (char) ((next & 0x0F) << 12);
} else {
throw new IOException(Msg.getString("K0065", (pos - 1)));
}
continue;
} else {
if ((next & 0xC0) != 0x80) {
throw new UTFDataFormatException(Msg.getString("K0064",
(pos - 1)));
}
switch (utf8Progress) {
case 1:
c |= (char) (next & 0x3F);
utf8Progress = 0;
break;
case 2:
utf8_2 = next;
utf8Progress = 3;
continue;
case 3:
c = (char) (()
| ((utf8_2 & 0x3F) << 6) | (next & 0x3F));
utf8Progress = 0;
}
}
[2] Popular stack traces show that the problem is no longer in archive implementation:
Ljava/nio/Buffer;.remaining()I:0
Lorg/apache/harmony/niochar/charset/UTF_8$Decoder;.decodeLoop(Ljava/nio/ByteBuffer;Ljava/nio/CharBuffer;)Ljava/nio/charset/CoderResult;:326
Ljava/nio/charset/CharsetDecoder;.decode(Ljava/nio/ByteBuffer;Ljava/nio/CharBuffer;Z)Ljava/nio/charset/CoderResult;:37
Ljava/util/jar/InitManifest;.decode(IIZ)V:34
Ljava/util/jar/InitManifest;.readValue()V:215
Ljava/util/jar/InitManifest;.readHeader()Z:25
Ljava/util/jar/InitManifest;.initEntries(Ljava/util/Map;Ljava/util/Map;)V:159
Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:89
Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
Ljava/net/URLClassLoader;.makeNewHandler()V:64
Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:103
Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Gregory Shimansky (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583176#action_12583176 ]
Gregory Shimansky commented on HARMONY-4569:
--------------------------------------------
Hmm to check whether the problem is actually fixed I took my agents and rerun the tests. I got the following two champions with the roots of stack traces going back to manifest parsing:
113450 Ljava/nio/Buffer;.remaining()I
105177 Lorg/apache/harmony/niochar/charset/UTF_8;.access$0()[I
Numbers before the names are the numbers of calls to run Hello World application. I agree that there is an improvement from ~300k calls to ~200K, but I am sure that the number of calls is still close to the number of bytes in all of Harmony JAR files manifest combined. Could something be done to this?...
If you think the problem is a different one, I'll close this bug as verified. Right now I am not convinced. Maybe it requires to resolve all of the currently open subtasks? In this case it is probably better to keep the parent JIRA to be open too.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583627#action_12583627 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Ok, I found a discussion. The arguments were explicitly named as forgotten. It seems that Anton repeated my suggestion of having sensible names and was not answered. Alex named performance problems with message bundles, and I recall a close problem in my experience. I may imagine that someone has some inliner for these messages and tries to keep them easier to parse, but reality seems simpler. Ilya just had started producing messages in this format on his own choice.
http://markmail.org/message/u4rrt2ss5oupjhgf
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12584360#action_12584360 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Gregory,
I have addressed remaining problems in the last subtask (HARMONY-5679).
Thanks!
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: remove_writes_todo.patch
Four TODO comments were added to the patch, so people who may want to improve the implementation further will be supported with another point of view.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_todo.patch
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: remove_writes_25032008.patch
A new patch (remove_writes_25032008.patch) improves the TODO comment in the previous patch by placing a defensive exception throwing if a user input triggers a buggy path in the code.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: remove_writes_todo_1.patch
The new patch version merges in HARMONY-5517 changes and r631925 by Stepan.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_todo.patch, remove_writes_todo_1.patch
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12573850#action_12573850 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
I have just checked that all invocations of
Ljava/io/ByteArrayOutputStream;.write(I)V: were removed.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp, remove_writes.patch
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583100#action_12583100 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Tim,
That's unbelievable. I'm grateful for your effort. Could you please help me to understand why you restored unreadable localization identifiers? With this change my removal of explanatory comments around them made code less understandable.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583346#action_12583346 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
Nathan,
Thank you for your answer. I'm sorry, it's hard for me to accept that anything we have in the code is conventional. Sometimes something that existed in the code, eg a bug or a duplicate function, was being changed if there was a sufficient reason for that change. I accept that sometimes things are kept in the bad shape intentionally, for example, due to insufficient resources. If we would set a clear goal to migrate to symbolic names, then any step would be good. But it seems that for some reason we might not want that goal. I'm missing something, and cannot understand what is it.
I may guess few reasons of having the numeric localization entries:
* one has localization tables for other languages which stick to this format
* one has a tool which operates with these numeric entries, making it them maintainable
* this is just a bad style we all don't like but bear since the migration would hardly be completed one day
It would be enough for me to specify explicitly that we don't want symbolic names even due to some unnamed reason, and I would be happy.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Tim Ellison (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583205#action_12583205 ]
Tim Ellison commented on HARMONY-4569:
--------------------------------------
> That's unbelievable.
What?
> I'm grateful for your effort. Could you please help me to understand why you
> restored unreadable localization identifiers? With this change my removal
> of explanatory comments around them made code less understandable.
Because we don't all go off inventing our own idea of how the code should be designed. You may disagree with the use of unreadable identifiers, and if so you should suggest they are changed throughout. Having the mixture of styles makes the code less understandable IMO.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: remove_writes_todo_completed.patch
The patch implements several TODO comments, including the following ones:
* Tim's suggestion to add ByteArrayInputStream child with exposed underlying buffer is implemented.
* The logic of Manifest parsing is structured via functions with descriptive names: readHeader, readName, readValue. A number of intermediate buffers are replaced with one thread local buffer.
* The manifest parsing is split into main attribute parsing and entry parsing. Delayed entry parsing is not enabled with this patch. Enabling it causes two JarInputStream verification test cases fail, the absence of entry information on some stage needs to be fixed.
* Removed duplication between o.a.h.archive.util.Util and o.a.h.luni.util.Util.
* Attribute names are now kept in byte arrays rather than character strings, equals is quickened by means of hash code. The cache for attribute names is removed since attribute creation is no longer a slow operation.
* The names of touched tests converted to Harmony convention.
* More manifest parsing tests, including reading and writing of characters encoded with several bytes. The test supports new CharsetEncoder/CharsetDecoder implementation.
* Thread local cache is used for string and byte buffers.
The patch incorporates previous patches and adds few new TODO comments.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Nathan Beyer (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583349#action_12583349 ]
Nathan Beyer commented on HARMONY-4569:
---------------------------------------
> Thank you for your answer. I'm sorry, it's hard for me to accept that anything we have in the code is conventional.
I'm not sure if I should take that as an insult or not.
> Sometimes something that existed in the code, eg a bug or a duplicate function, was being changed if there was a sufficient reason for that change. I accept that sometimes things are kept in the bad shape intentionally, for example, due to insufficient resources. If we would set a clear goal to migrate to symbolic names, then any step would be good. But it seems that for some reason we might not want that goal. I'm missing something, and cannot understand what is it.
Again, I'm not sure how to take this either. Even though you may not like it, it doesn't make it a bug, incorrect, inappropriate or bad.
If you really want to discuss this farther, then please pull it onto the mailing list.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Tim Ellison (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12585089#action_12585089 ]
Tim Ellison commented on HARMONY-4569:
--------------------------------------
please move discussion and analysis onto the dev list -- thanks
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Assigned: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Tim Ellison (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Tim Ellison reassigned HARMONY-4569:
------------------------------------
Assignee: Tim Ellison
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12568656#action_12568656 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
My current assumptions are:
1. If InputStream would be replaced with byte[] in InitManifest constructor, this would result in simpler work with chunks coded with begin/length integer number pairs.
2. The chunks are important for JarVerifier only, may be it is sufficient to create them only when jar file is verified. Verification result may be cached anyway.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12568605#action_12568605 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
The write() call is used to populate byte arrays which are manifest chunks. These chunks are only used sequentially in JarVerifier class, so creating a hash map of the chunk copies one may use their boundary indices in the manifest. It would be great if an author of original code would comment why he chose to populate a hash table with manifest substrings.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Resolved: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Tim Ellison (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Tim Ellison resolved HARMONY-4569.
----------------------------------
Resolution: Fixed
Thanks Gregory/Alexei.
Patches applied (virtually) unmodified at repo revision r641928.
I do have some minor/cosmetic suggestions, but wanted to get this in place and we can tweak the code there.
Please verify it was applied as you expected.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: ExposedByteArrayInputStream.java
ThreadLocalCache.java
ByteBuffer.java
These new files should be added to working_classlib\modules\luni\src\main\java\org\apache\harmony\luni\util
* ExposedByteArrayInputStream extends ByteArrayInputStream to provide access to the underlying buffer
* ByteBuffer gets the underlying buffer for a ByteArrayInputStream and provides a unified wrap(InputStream) call which returns a byte snapshot of the stream
* ThreadLocalCache is self cleaning ThreadLocal
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Gregory Shimansky (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Gregory Shimansky updated HARMONY-4569:
---------------------------------------
Attachment: methodee-stack.cpp
methodee.cpp
I'm attaching agents sources with permission for ASF to use them. So it is possible for other people to modify and use this code.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Naumova Natalya (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12569917#action_12569917 ]
Naumova Natalya commented on HARMONY-4569:
-------------------------------------------
The reason of such big number of "ByteArrayOutputStream;.write" invokes is signed ext/bcprov.jar - it's manifest is read by byte. If we put this jar to bootclasspath we'll have at least 5% performance boost on HWA application .
btw: maybe we should add this Jira's as subtasks to HARMONY-5277 ? As they're startup related.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12583624#action_12583624 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
This is not exactly a convention description, but at least it was mentioned here, http://markmail.org/message/w5rsyyv45zkezld2
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Assignee: Tim Ellison
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Updated: (HARMONY-4569) [classlib][performance] Ineffecient
manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:all-tabpanel ]
Alexei Fedotov updated HARMONY-4569:
------------------------------------
Attachment: remove_writes.patch
The patch removes chunk creation during jar verification. It can be simplified further as well as contains the bugs original code had. All tests passed, so this is a good intermediate step.
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: methodee-stack.cpp, methodee.cpp, remove_writes.patch
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.
[jira] Commented: (HARMONY-4569) [classlib][performance]
Ineffecient manifest parsing results in slowdown when debugging java code
Posted by "Alexei Fedotov (JIRA)" <ji...@apache.org>.
[ https://issues.apache.org/jira/browse/HARMONY-4569?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=12582704#action_12582704 ]
Alexei Fedotov commented on HARMONY-4569:
-----------------------------------------
There are four cumulative artifacts to review and commit:
the patch
remove_writes_25032008.patch
three new files to svn add to working_classlib\modules\luni\src\main\java\org\apache\harmony\luni\util:
ExposedByteArrayInputStream ByteBuffer and ThreadLocalCache
Please let me know if I need to separate particular changes for easier review (would require some time).
> [classlib][performance] Ineffecient manifest parsing results in slowdown when debugging java code
> -------------------------------------------------------------------------------------------------
>
> Key: HARMONY-4569
> URL: https://issues.apache.org/jira/browse/HARMONY-4569
> Project: Harmony
> Issue Type: Bug
> Components: Classlib
> Reporter: Gregory Shimansky
> Attachments: ByteBuffer.java, ExposedByteArrayInputStream.java, methodee-stack.cpp, methodee.cpp, remove_writes.patch, remove_writes_25032008.patch, remove_writes_todo.patch, remove_writes_todo_1.patch, remove_writes_todo_completed.patch, ThreadLocalCache.java
>
>
> I've reported this already some time ago [1], but since it wasn't noticed I decided to create a bug report.
> To run a hello world class which contains only 1 method takes 319046 method calls on Harmony. Out of them 291637 method calls are the calls that happen when Java class loader tries to find Hello.class and 27409 are what it takes for classlib to startup.
> I've found these numbers using two simple JVMTI agents that I wrote some time ago. First one [2] counts all MethodEnter events and outputs method names to log file. Second one [3] monitors a particular method and writes down a stack trace to the log file. It should be noted that MethodEnter event according to specification is sent by VM only in LIVE phase, that is after classlib startup, so to find out the overall number of method calls I've used debug version of DRLVM with an additional argument -Xtrace:jvmti.event.method.entry:log which wrote down *all* of the calls to Java method while executing the application.
> Parsing the logs for statistics can be done with the following command:
> cat method_entry.log | sort | uniq -c | sort -nr > method_entry.log-sorted
> It creates a file with the number that each method was called. The absolute champion since my post in [1] still remains the method Ljava/io/ByteArrayOutputStream;.write(I)V, it is called 131114 times. Using second agent [3] I've found out that the most popular stack trace for calling ByteArrayOutputStream;.write looks like this (please note that numbers at the ends of the lines are not line numbers, these are the bytecode numbers):
> Ljava/io/ByteArrayOutputStream;.write(I)V:0
> Ljava/util/jar/InitManifest;.nextChunk(Ljava/io/InputStream;Ljava/util/List;)[B:308
> Ljava/util/jar/InitManifest;.<init>(Ljava/io/InputStream;Ljava/util/jar/Attributes;Ljava/util/Map;Ljava/util/Map;Ljava/lang/String;)V:385
> Ljava/util/jar/Manifest;.read(Ljava/io/InputStream;)V:18
> Ljava/util/jar/Manifest;.<init>(Ljava/io/InputStream;Z)V:43
> Ljava/util/jar/JarFile;.getManifest()Ljava/util/jar/Manifest;:90
> Ljava/net/URLClassLoader;.createURLJarHandler(Ljava/net/URL;)Ljava/net/URLClassLoader$URLHandler;:141
> Ljava/net/URLClassLoader;.makeNewHandler()V:64
> Ljava/net/URLClassLoader;.getHandler(I)Ljava/net/URLClassLoader$URLHandler;:24
> Ljava/net/URLClassLoader;.findClassImpl(Ljava/lang/String;)Ljava/lang/Class;:82
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Class;:8
> Ljava/net/URLClassLoader$4;.run()Ljava/lang/Object;:1
> Ljava/security/AccessController;.doPrivilegedImpl(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:79
> Ljava/security/AccessController;.doPrivileged(Ljava/security/PrivilegedAction;Ljava/security/AccessControlContext;)Ljava/lang/Object;:16
> Ljava/net/URLClassLoader;.findClass(Ljava/lang/String;)Ljava/lang/Class;:13
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:80
> Ljava/lang/ClassLoader$SystemClassLoader;.loadClass(Ljava/lang/String;Z)Ljava/lang/Class;:65
> Ljava/lang/ClassLoader;.loadClass(Ljava/lang/String;)Ljava/lang/Class;:3
> This stack trace occurs 123029 number of times, about 8000 times ByteArrayOutputStream;.write is called from InitManifest class with a bit different stack trace, but all of the calls to write occur from this class. It seems that InitManifest code copies memory by bytes and there is quite a lot of the memory that is copied. This may not be a big problem in the normal execution of Java application because JIT usually inlines such hot methods. Although it is still inefficient, it may be not a big performance hit (actually this should be checked).
> But when trying to debug Java code, DRLVM uses JET, which doesn't inline any methods. It has to execute all of them and all of those calls to ByteArrayOutputStream;.write are executed on startup of the application. It takes several minutes to get to the point of executing the actual user program.
> [1] http://thread.gmane.org/gmane.comp.java.harmony.devel/21104/focus=21133 see also messages posted in this subthread by me
> [2] http://people.apache.org/~gshimansky/methodee.cpp
> [3] http://people.apache.org/~gshimansky/methodee-stack.cpp
--
This message is automatically generated by JIRA.
-
You can reply to this email to add a comment to the issue online.