2

I'm oberserving extreme long running requests (>30s) in a Java 8 / Spring 5 / Tomcat 8.5 web application. The majority of requests responds normally. It's remarkable that the frequency of long runners increases after some days of uptime.

Threaddumps show that Unsafe.defineClass is hanging:

at sun.misc.Unsafe.defineClass(Native Method) 
at sun.reflect.ClassDefiner.defineClass(ClassDefiner.java:63) 
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399) 
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:394) 
at java.security.AccessController.doPrivileged(Native Method)  
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:393) 
at sun.reflect.MethodAccessorGenerator.generateMethod(MethodAccessorGenerator.java:75) 
at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:53) 
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43) 
at java.lang.reflect.Method.invoke(Method.java:498) 
at org.springframework.core.annotation.AnnotationUtils.getValue(AnnotationUtils.java:1328)  
at org.springframework.core.annotation.AnnotatedElementUtils$MergedAnnotationAttributesProcessor.getAdaptedValue(AnnotatedElementUtils.java:1627) 
at org.springframework.core.annotation.AnnotatedElementUtils$MergedAnnotationAttributesProcessor.overrideAttributes(AnnotatedElementUtils.java:1610) 
at org.springframework.core.annotation.AnnotatedElementUtils$MergedAnnotationAttributesProcessor.postProcess(AnnotatedElementUtils.java:1598) 
at org.springframework.core.annotation.AnnotatedElementUtils$MergedAnnotationAttributesProcessor.postProcess(AnnotatedElementUtils.java:1515) 
at org.springframework.core.annotation.AnnotatedElementUtils.searchWithFindSemantics(AnnotatedElementUtils.java:1145) 
at org.springframework.core.annotation.AnnotatedElementUtils.searchWithFindSemantics(AnnotatedElementUtils.java:1066) 
at org.springframework.core.annotation.AnnotatedElementUtils.searchWithFindSemantics(AnnotatedElementUtils.java:1038) 
at org.springframework.core.annotation.AnnotatedElementUtils.findMergedAnnotationAttributes(AnnotatedElementUtils.java:650) 
at org.springframework.core.annotation.AnnotatedElementUtils.findMergedAnnotation(AnnotatedElementUtils.java:726)
....

Has anybody ever seen this problem?

chrempl
  • 91
  • 1
  • 5
  • Created a separate question for my jstack issue: https://stackoverflow.com/questions/49516601/jstack-in-mixed-mode-wrongtypeexception-no-suitable-match-for-type-of-address – chrempl Mar 27 '18 at 15:14

1 Answers1

0

Could it be that you are running out of Metaspace either by using a conservative -XX:MaxMetaspaceSize or not having enough RAM on the server? Since GC runs on Metaspace your slowness might be the result of it struggling to clean it. By default the Metaspace memory is collected if it reaches the MaxMetaspaceSize so this 30 sec pause might be the GC.

There is however a bigger question. What in your code is allocating these classes and why does it happen often enough to fill Metaspace. Normally classes are created during startup and after that much less frequently. Perhaps you are doing hot deployments and the ClassLoader is leaking?

In pre Java 8 this could be caused by the GC and PermGen running out e.g. as asked in this question where it caused OutOfMemoryError.

Karol Dowbecki
  • 43,645
  • 9
  • 78
  • 111
  • Yes, i'm limiting MaxMetaspaceSize. But only 75% is used. More than 6GB RAM is free. – chrempl Mar 27 '18 at 08:58
  • @chrempl Is the 75% usage constant even when the slowness happens? Could also be the Metaspace expansion, either way debugging GC on Metaspace should give you the answer. – Karol Dowbecki Mar 27 '18 at 09:01
  • yes, metaspace usage is constant. Garbage collection (G1) times are also fine. – chrempl Mar 27 '18 at 09:19
  • Just for clarification, i have to point out that these classes are generated by java reflection internals. It's not my code. I also suspected classloader locks - but there are not monitors in the threaddumps. – chrempl Mar 27 '18 at 10:26