Story of how we reduced app startup time by 20x and heap usage by 7x
Few months ago, we started developing a Spring Boot app in Groovy. It is a typical app with ton of CRUD logic and few REST endpoints. It also had a Swagger UI configured with SpringFox Swagger. Though it was taking ~35 seconds to start and taking ~700MB heap space, no-one in the team really cared about the slowness and memory usage of the application.
As our application grew bigger, we added more DB tables and endpoints which resulted in further slowness and required more heap space. It was ~3 minutes startup with almost 1.4GB heap at its worst state. Again no-one really bothered to fix it... until the application randomly failed to start and started crashing randomly with OutOfMemoryError.
Problem Identification: Thread Dump using IntelliJ
 |
| The IntelliJ thread-dump showing the main thread always stuck at springfox |
I started the application in debug mode in IntelliJ and took thread dump several times to see what's the main thread is doing. I found that in all thread dumps, the main thread was stuck around springfox.documentation.spring.web.readers.parameter.ModelAttributeParameterExpander.expand() method.
So, I dig into the ModelAttributeParameterExpander#expand() method was able to quickly confirm that it was trying to expand the fields from the @ModelAttribute to render into the Swagger UI - which is exposed in a JSON endpoint host:port/v3/api-docs.
Once the application started (after about 3 mins), I opened up the host:port/v3/api-docs endpoint locally and amazed by the size of JSON response. It WAS 1240MB! That explained why Swagger UI used to take longer.Problem Isolation:
To isolate the problem, I commented out all the endpoints that's using @ModelAttribute and just like I expected, the app started within 9 seconds, took about 200MB heap, the swagger UI loaded within one second, the host:port/v3/api-docs endpoint response was about 20KB.
@GetMapping("/test")
void test(@ModelAttribute A a) { //commented out all the endpoints to isolate problem
Then I dig through the code inside ModelAttributeParameterExpander#expand() and I found that its collecting all the fields and properties inside the @ModelAttribute class and recursively calls the expand() method for all the sub-fields and properties.
public List<Compatibility<Parameter, RequestParameter>> expand(ExpansionContext context) {
List<Compatibility<Parameter, RequestParameter>> parameters = new ArrayList();
Set<PropertyDescriptor> propertyDescriptors = this.propertyDescriptors(context.getParamType().getErasedType());
Map<Method, PropertyDescriptor> propertyLookupByGetter = this.propertyDescriptorsByMethod(context.getParamType().getErasedType(), propertyDescriptors);
Iterable<ResolvedMethod> getters = (Iterable)this.accessors.in(context.getParamType()).stream().filter(this.onlyValidGetters(propertyLookupByGetter.keySet())).collect(Collectors.toList());
...
Stream<ModelAttributeField> collectionTypes = attributes.stream().filter(this.isCollection().and(this.recursiveCollectionItemType(context.getParamType()).negate()));
collectionTypes.forEachOrdered((each) -> {
....
parameters.addAll(this.expand(childContext)); //nested
I dig further and found that it was grabing the getMetaClass method generated by Groovy and recursively looking at all the get* methods and the parameters inside MetaClass class.
public static class MyClass implements GroovyObject {
//..fields
@Generated
@Internal
@Transient
public MetaClass getMetaClass() { //this was treated as class property
MetaClass: it contains several get* method. All of them were processed by Swagger
public interface MetaClass extends MetaObjectProtocol {
Object invokeMethod(Class var1, Object var2, String var3, Object[] var4, boolean var5, boolean var6);
Object getProperty(Class var1, Object var2, String var3, boolean var4, boolean var5);
void setProperty(Class var1, Object var2, String var3, Object var4, boolean var5, boolean var6);
Object invokeMissingMethod(Object var1, String var2, Object[] var3);
Object invokeMissingProperty(Object var1, String var2, Object var3, boolean var4);
Object getAttribute(Class var1, Object var2, String var3, boolean var4);
void setAttribute(Class var1, Object var2, String var3, Object var4, boolean var5, boolean var6);
void initialize();
List<MetaProperty> getProperties();
List<MetaMethod> getMethods();
ClassNode getClassNode();
List<MetaMethod> getMetaMethods();
int selectConstructorAndTransformArguments(int var1, Object[] var2);
MetaMethod pickMethod(String var1, Class[] var2);
}
Solution:
I found that there were few discussions already in springfox GitHub project and solution was also discussed. The solution is to configure the Docket object to ignore MetaClass class using ignoredParameterTypes() method:
@Bean
Docket docket(){
new Docket(DocumentationType.OAS_30)
.ignoredParameterTypes(MetaClass)
}
}
Now the application takes about 9 seconds to start and takes about 200MB heap space. That was a great reduction from 3min/1.4GB.
Reproducible example:
The following simple app was taking 10 seconds to start, the http://localhost:8080/v3/api-docs returns 58.5MB JSON response. Once I comment out the test method and rerun it just takes 1.7 seconds. Also, the http://localhost:8080/v3/api-docs returns 5KB JSON response.
package gt.swagger.demo
import org.springframework.boot.SpringApplication
import org.springframework.boot.autoconfigure.SpringBootApplication
import org.springframework.web.bind.annotation.*
import springfox.documentation.swagger2.annotations.EnableSwagger2
@SpringBootApplication
@EnableSwagger2
class SwaggerTestApp {
static void main(String[] args) {
SpringApplication.run(SwaggerTestApp, args)
}
}
@RestController
class Controller {
@GetMapping("/test")
void test(@ModelAttribute A a) {
}
static class A {
String a
}
}
When I add more endpoints with @ModelAttribute or when I nest the 'A' class with class B, the application starts taking a lot of time to start and takes up more heap space
static class A {
String a
B b1, b2, b3, b4, b5 ,b6, b7, b8, b9
}
static class B {
String b
}
The problem can be solved by configuring the following bean:
@Configuration
class SwaggerConfig {
@Bean
Docket docket(){
new Docket(DocumentationType.OAS_30)
.ignoredParameterTypes(MetaClass)
}
}
POM.xml:
<?xml version="1.0" encoding="UTF-8"?>
<project xmlns="http://maven.apache.org/POM/4.0.0" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://maven.apache.org/POM/4.0.0 https://maven.apache.org/xsd/maven-4.0.0.xsd">
<modelVersion>4.0.0</modelVersion>
<parent>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-parent</artifactId>
<version>2.5.2</version>
<relativePath/> <!-- lookup parent from repository -->
</parent>
<groupId>gt.swagg</groupId>
<artifactId>sb25-swagger3</artifactId>
<version>0.0.1-SNAPSHOT</version>
<packaging>jar</packaging>
<properties>
<java.version>11</java.version>
</properties>
<dependencies>
<dependency>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-starter-web</artifactId>
</dependency>
<dependency>
<groupId>io.springfox</groupId>
<artifactId>springfox-boot-starter</artifactId>
<version>3.0.0</version>
</dependency>
<dependency>
<groupId>org.codehaus.groovy</groupId>
<artifactId>groovy</artifactId>
</dependency>
</dependencies>
<build>
<plugins>
<plugin>
<groupId>org.springframework.boot</groupId>
<artifactId>spring-boot-maven-plugin</artifactId>
</plugin>
<plugin>
<groupId>org.codehaus.gmavenplus</groupId>
<artifactId>gmavenplus-plugin</artifactId>
<version>1.11.0</version>
<executions>
<execution>
<goals>
<goal>addSources</goal>
<goal>addTestSources</goal>
<goal>generateStubs</goal>
<goal>compile</goal>
<goal>generateTestStubs</goal>
<goal>compileTests</goal>
<goal>removeStubs</goal>
<goal>removeTestStubs</goal>
</goals>
</execution>
</executions>
</plugin>
</plugins>
</build>
</project>
Lesson learned:
- Pay attention on why your application is starting slow. Even a small mis-configuration like this might use up lots of resources
- Developer hour cost $$$. Make sure developers are not burning $$$ on non-trivial things like the slow application start
- Focus on how to increase developer productivity. I have seen devs compiling the whole project after every change to test it. Watch/educate developers to see if they are using the tools correctly
- Java/JVM is fast. Like every other programming language, developers can misuse/misconfigure it to make it slow
- etc
