Review startup times for a large, legacy Spring Application

[tkvangorder]

Please feel free to DM me on twitter @tkvangorder, I am at SpringOne until Thursday afternoon (although, I could extend some time afterwards if necessary. I know your schedule is likely a lot more impacted than me. If it doesnt work out in your schedule, I totally understand.

[tkvangorder]

This is issue I raised around lazy loading all beans when in running in a unit test profile. We have found it pretty useful in our large app when running integration tests.

spring-projects/spring-boot#9685

[tkvangorder]

@dsyer I have some new information on the startup footprint for our application. Please let me know if you have any questions or are in need of more information. Not sure if it makes sense to open up a new issue in Spring Boot repo for the rebinder?

Thanks!

TL;DR;

• Mybatis - I recorded the time it takes Mybatis to create each mapper implementation and parse the Mapper xml file. The total time spent to parse all 95 mappers was 1.6 seconds (out of 40 total), so while not insignificant, it was also not the silver bullet.

• @PostConstruct - I then started looking for badly behaving methods that were annotated with @PostConstruct and I was able to locate 4 that were contributing up to 5 seconds. So this is an easy win for us, I am going to refactor these to use a lazy loading approach.

• ConfigurationPropertiesRebinder - This last one was tricky to hunt down, it manifests itself at the very end of the boot process. On my development machine, this black hole of time was almost always 5 seconds. I finally isolated by using JMC to profile what was going on during just those five seconds and I was very surprised to see the hotspot was in ConfigurationPropertiesRebinder.rebind(). This is the one I am going to need your help on, as I don't see an immediate solution. I know you have reworked the relaxed binding in the 2.0.x branch but I am hoping you might be able to find some type of solution on the 1.5.x branch.

The details:

My approach with each use case was brute force, I just cloned each library and added some well placed timing code:

Mybatis:

org.mybatis.spring.mapper.MapperFactoryBean.checkDaoConfig():

  protected void checkDaoConfig() {
    super.checkDaoConfig();

    notNull(this.mapperInterface, "Property 'mapperInterface' is required");

    Configuration configuration = getSqlSession().getConfiguration();
    if (this.addToConfig && !configuration.hasMapper(this.mapperInterface)) {
      try {
    	long start = System.currentTimeMillis();
        configuration.addMapper(this.mapperInterface);
        logger.info("Loaded Mapper '" + this.mapperInterface + "' in " + (System.currentTimeMillis() - start) + "ms."); 
      } catch (Exception e) {
        logger.error("Error while adding the mapper '" + this.mapperInterface + "' to configuration.", e);
        throw new IllegalArgumentException(e);
      } finally {
        ErrorContext.instance().reset();
      }
    }
  }

PostConstruct:

I have opened up a suggested issue to include timing logic around the calls to each post construct method. https://jira.spring.io/browse/SPR-16287

ConfigurationPropertiesRebinder.rebind:

	public boolean rebind(String name) {
		if (!this.beans.getBeanNames().contains(name)) {
			return false;
		}
		if (this.applicationContext != null) {
			try {
				Object bean = this.applicationContext.getBean(name);
				if (AopUtils.isCglibProxy(bean)) {
					bean = getTargetObject(bean);
				}
				long start = System.currentTimeMillis();
				this.binder.postProcessBeforeInitialization(bean, name);
				this.applicationContext.getAutowireCapableBeanFactory().initializeBean(bean, name);
				logger.debug("Rebind on Bean [" + name + "] took " + (System.currentTimeMillis() - start) + "ms");
				return true;
			}
			catch (RuntimeException e) {
				this.errors.put(name, e);
				throw e;
			}
		}
		return false;
	}

For reference, looking at the /env actuator endpoint, there are just over a 1000 properties across 13 property sources.

Here is the logging I am seeing in our legacy application, again, just timing the call around rebind(String beanName):

Rebind on Bean [channelAdvisorServiceSettings] took 95ms
Rebind on Bean [spoolServiceImpl] took 1ms
Rebind on Bean [cache-com.build.cache.config.CacheSettings] took 4ms
Rebind on Bean [houzzReportsSettings] took 20ms
Rebind on Bean [bluetarpReportsSettings] took 41ms
Rebind on Bean [cartSettings] took 5ms
Rebind on Bean [generalElectricSettings] took 70ms
Rebind on Bean [healthMvcEndpoint] took 34ms
Rebind on Bean [geoIp2Settings] took 8ms
Rebind on Bean [serverProperties] took 54ms
Rebind on Bean [mainDataSource] took 753ms
Rebind on Bean [shippingSettings] took 8ms
Rebind on Bean [loggersMvcEndpoint] took 26ms
Rebind on Bean [vyzeSettings] took 60ms
Rebind on Bean [shutdownEndpoint] took 23ms
Rebind on Bean [leadTimeOverrideRuleSettings] took 25ms
Rebind on Bean [cloudinarySettings] took 15ms
Rebind on Bean [salesForceObjectSettings] took 7ms
Rebind on Bean [spring.webservices-org.springframework.boot.autoconfigure.webservices.WebServicesProperties] took 7ms
Rebind on Bean [phaxioSettings] took 9ms
Rebind on Bean [requestMappingEndpoint] took 41ms
Rebind on Bean [amazonPaymentSettings] took 79ms
Rebind on Bean [spring.cloud.config.retry-org.springframework.cloud.config.client.RetryProperties] took 29ms
Rebind on Bean [blueTarpSettings] took 24ms
Rebind on Bean [contentSettings] took 16ms
Rebind on Bean [paintApiSettings] took 31ms
Rebind on Bean [cyberSourceReportsSettings] took 91ms
Rebind on Bean [cloudConversionSettings] took 45ms
Rebind on Bean [spring.redis-org.springframework.boot.autoconfigure.data.redis.RedisProperties] took 38ms
Rebind on Bean [feiSettings] took 26ms
Rebind on Bean [spring.http.multipart-org.springframework.boot.autoconfigure.web.MultipartProperties] took 2ms
Rebind on Bean [resumeEndpoint] took 19ms
Rebind on Bean [googleFormDataSettings] took 5ms
Rebind on Bean [liquidityFeedSettings] took 32ms
Rebind on Bean [nasSettings] took 4ms
Rebind on Bean [auditEventMvcEndpoint] took 34ms
Rebind on Bean [restartEndpoint] took 49ms
Rebind on Bean [activitySettings] took 16ms
Rebind on Bean [provideEdiDynamicSegmentMapper] took 7ms
Rebind on Bean [healthEndpoint] took 23ms
Rebind on Bean [configClientProperties] took 54ms
Rebind on Bean [spring.cloud.config-org.springframework.cloud.bootstrap.config.PropertySourceBootstrapProperties] took 26ms
Rebind on Bean [endpoints.metrics.filter-org.springframework.boot.actuate.autoconfigure.MetricFilterProperties] took 12ms
Rebind on Bean [securityProperties] took 20ms
Rebind on Bean [dumpEndpoint] took 14ms
Rebind on Bean [encrypt-org.springframework.cloud.bootstrap.encrypt.KeyProperties] took 12ms
Rebind on Bean [pauseEndpoint] took 19ms
Rebind on Bean [wordPressSettings] took 13ms
Rebind on Bean [blueTarpApiClientSettings] took 33ms
Rebind on Bean [hystrix.metrics-org.springframework.cloud.netflix.hystrix.HystrixMetricsProperties] took 12ms
Rebind on Bean [overstockReportsSettings] took 9ms
Rebind on Bean [wedgewoodSettings] took 62ms
Rebind on Bean [endpoints.health-org.springframework.boot.actuate.autoconfigure.HealthMvcEndpointProperties] took 5ms
Rebind on Bean [walmartReportsSettings] took 24ms
Rebind on Bean [bazaarVoiceApiSettings] took 25ms
Rebind on Bean [spring.mvc-org.springframework.boot.autoconfigure.web.WebMvcProperties] took 123ms
Rebind on Bean [smsSettings] took 32ms
Rebind on Bean [com.build.cloud.discovery.BuildEurekaAutoConfiguration] took 22ms
Rebind on Bean [endpoints-org.springframework.boot.actuate.endpoint.EndpointProperties] took 2ms
Rebind on Bean [management.info-org.springframework.boot.actuate.autoconfigure.InfoContributorProperties] took 5ms
Rebind on Bean [metricsEndpoint] took 12ms
Rebind on Bean [spoolSettings] took 5ms
Rebind on Bean [inetUtilsProperties] took 39ms
Rebind on Bean [constructSettings] took 16ms
Rebind on Bean [emailSettings] took 8ms
Rebind on Bean [categorySettings] took 4ms
Rebind on Bean [featuresEndpoint] took 2ms
Rebind on Bean [taxServiceSettings] took 76ms
Rebind on Bean [spring.rabbitmq-org.springframework.boot.autoconfigure.amqp.RabbitProperties] took 81ms
Rebind on Bean [environmentEndpoint] took 25ms
Rebind on Bean [ssoSettings] took 9ms
Rebind on Bean [salesForceSettings] took 14ms
Rebind on Bean [autoPmgSettings] took 21ms
Rebind on Bean [configClientHealthProperties] took 14ms
Rebind on Bean [spring.cloud.service-registry.auto-registration-org.springframework.cloud.client.serviceregistry.AutoServiceRegistrationProperties] took 4ms
Rebind on Bean [configurationPropertiesReportEndpoint] took 29ms
Rebind on Bean [linkShareSettings] took 11ms
Rebind on Bean [loggersEndpoint] took 13ms
Rebind on Bean [ribbon.eager-load-org.springframework.cloud.netflix.ribbon.RibbonEagerLoadProperties] took 7ms
Rebind on Bean [phaxioService] took 1ms
Rebind on Bean [awsSettings] took 20ms
Rebind on Bean [spring.http.encoding-org.springframework.boot.autoconfigure.web.HttpEncodingProperties] took 29ms
Rebind on Bean [shortenUrlSettings] took 7ms
Rebind on Bean [beansEndpoint] took 22ms
Rebind on Bean [vendorInventorySettings] took 69ms
Rebind on Bean [signifydSettings] took 13ms
Rebind on Bean [cyberSourceSettings] took 31ms
Rebind on Bean [ediSettings] took 8ms
Rebind on Bean [upsSettings] took 25ms
Rebind on Bean [vendorShipTimeSettings] took 7ms
Rebind on Bean [spring.transaction-org.springframework.boot.autoconfigure.transaction.TransactionProperties] took 15ms
Rebind on Bean [customerSettings] took 7ms
Rebind on Bean [spring.data.mongodb-org.springframework.boot.autoconfigure.mongo.MongoProperties] took 57ms
Rebind on Bean [searchRedirectSetting] took 61ms
Rebind on Bean [spring.jackson-org.springframework.boot.autoconfigure.jackson.JacksonProperties] took 66ms
Rebind on Bean [jetReportsSettings] took 17ms
Rebind on Bean [endpoints.cors-org.springframework.boot.actuate.autoconfigure.EndpointCorsProperties] took 58ms
Rebind on Bean [heapdumpMvcEndpoint] took 41ms
Rebind on Bean [environmentMvcEndpoint] took 28ms
Rebind on Bean [spring.info-org.springframework.boot.autoconfigure.info.ProjectInfoProperties] took 8ms
Rebind on Bean [spring.datasource-org.springframework.boot.autoconfigure.jdbc.DataSourceProperties] took 156ms
Rebind on Bean [metricsMvcEndpoint] took 22ms
Rebind on Bean [traceEndpoint] took 12ms
Rebind on Bean [infoEndpoint] took 14ms
Rebind on Bean [spring.cloud.loadbalancer.retry-org.springframework.cloud.client.loadbalancer.LoadBalancerRetryProperties] took 3ms
Rebind on Bean [eurekaClientConfigBean] took 445ms
Rebind on Bean [management.trace-org.springframework.boot.actuate.trace.TraceProperties] took 4ms
Rebind on Bean [spring.resources-org.springframework.boot.autoconfigure.web.ResourceProperties] took 2ms
Rebind on Bean [amazonMarketplaceSettings] took 122ms
Rebind on Bean [management.health.status-org.springframework.boot.actuate.autoconfigure.HealthIndicatorProperties] took 4ms
Rebind on Bean [amazonVendorSettingsList] took 11ms
Rebind on Bean [pivotFreightSettings] took 125ms
Rebind on Bean [vmeSettings] took 11ms
Rebind on Bean [spifSettings] took 18ms
Rebind on Bean [jasperSettings] took 5ms
Rebind on Bean [socialLoginSettings] took 9ms
Rebind on Bean [autoConfigurationReportEndpoint] took 13ms
Rebind on Bean [solrSettings] took 18ms
Rebind on Bean [homeAdvisorServiceSettings] took 42ms

[dsyer]

That's good data. Maybe time for some optimization in spring-cloud-context. It might be worth trying Spring Boot 2.0 (even though there is a startup time issue there since 2.0.0.M3) because property binding is a lot faster now. I also noticed that a few of the expensive beans in the list above were yours, so maybe they are still doing unnecessary stuff in @PostConstruct?

[dsyer]

I tried commenting out that line in ConfigurationPropertiesRebinderAutoConfiguration

	@Override
	public void afterSingletonsInstantiated() {
		// After all beans are initialized send a pre-emptive EnvironmentChangeEvent
		// so that anything that needs to rebind gets a chance now (especially for
		// beans in the parent context)
		 this.context
		   .publishEvent(new EnvironmentChangeEvent(Collections.<String>emptySet()));
	}

and I don't see anything really bad happening. You could try doing that and see if it gets you back your 5 seconds. I'll have a think about why it was there originally.

[tkvangorder]

Commenting out the publishEvent does indeed fix the issue, I am down to 27 seconds (and I have still not fixed our PostConstruct issues). Assuming there are no side effects from that, that is awesome!

As for your first question, most of the beans being rebound are straight Java beans (properties, getters/setter).

The most expensive one, "mainDataSource" is just a jdbc DataSource and the bean definition looks like this:

	@Bean(name = "mainDataSource", destroyMethod="")
	@Primary
	@ConfigurationProperties(prefix = "datasource.main")
	public DataSource driverManagerMainDataSource() {
		return DataSourceBuilder.create().build();
	}

One of the more expensive beans that is ours:

@Component
@ConfigurationProperties(prefix = "amazon.marketplace")
public class AmazonMarketplaceSettings {

	private int marketplaceId;
	private String merchantId;
	private String mwsMarketplaceId;
	private String reportsOutputPath;
	private String submissionResultsOutputPath;

	private String awsAccessKeyId;
	private String awsSecretAccessKey;
	private String applicationName;
	private String applicationVersion;
	private String configServiceUrl;

	private String merchantToken;

	private Map<Integer, AmazonAPICredential> storeCredentialMap;
	private Map<String, String> serviceUrlMap;

	public int getMarketplaceId() {
		return marketplaceId;
	}

	public void setMarketplaceId(int marketplaceId) {
		this.marketplaceId = marketplaceId;
	}

	public void setMerchantId(String merchantId) {
		this.merchantId = merchantId;
	}

	public String getMerchantId() {
		return merchantId;
	}

	public void setMwsMarketplaceId(String mwsMarketplaceId) {
		this.mwsMarketplaceId = mwsMarketplaceId;
	}

	public String getMwsMarketplaceId() {
		return mwsMarketplaceId;
	}

	public String getReportsOutputPath() {
		return reportsOutputPath;
	}

	public void setReportsOutputPath(String reportsOutputPath) {
		this.reportsOutputPath = reportsOutputPath;
	}

	public String getSubmissionResultsOutputPath() {
		return submissionResultsOutputPath;
	}

	public void setSubmissionResultsOutputPath(
			String submissionResultsOutputPath) {
		this.submissionResultsOutputPath = submissionResultsOutputPath;
	}

	public String getAwsAccessKeyId() {
		return awsAccessKeyId;
	}

	public void setAwsAccessKeyId(String awsAccessKeyId) {
		this.awsAccessKeyId = awsAccessKeyId;
	}

	public String getAwsSecretAccessKey() {
		return awsSecretAccessKey;
	}

	public void setAwsSecretAccessKey(String awsSecretAccessKey) {
		this.awsSecretAccessKey = awsSecretAccessKey;
	}

	public String getApplicationName() {
		return applicationName;
	}

	public void setApplicationName(String applicationName) {
		this.applicationName = applicationName;
	}

	public String getApplicationVersion() {
		return applicationVersion;
	}

	public void setApplicationVersion(String applicationVersion) {
		this.applicationVersion = applicationVersion;
	}

	public String getConfigServiceUrl() {
		return configServiceUrl;
	}

	public void setConfigServiceUrl(String configServiceUrl) {
		this.configServiceUrl = configServiceUrl;
	}

	public String getMerchantToken() {
		return merchantToken;
	}

	public void setMerchantToken(String merchantToken) {
		this.merchantToken = merchantToken;
	}

	public Map<Integer, AmazonAPICredential> getStoreCredentialMap() {
		return storeCredentialMap;
	}

	public void setStoreCredentialMap(Map<Integer, AmazonAPICredential> storeCredentialMap) {
		this.storeCredentialMap = storeCredentialMap;
	}

	public Map<String, String> getServiceUrlMap() {
		return serviceUrlMap;
	}

	public void setServiceUrlMap(Map<String, String> serviceUrlMap) {
		this.serviceUrlMap = serviceUrlMap;
	}
}

And the nested AmazonAPICredential:

public class AmazonAPICredential implements Serializable {
	private static final long serialVersionUID = 1L;

	private Integer storeId;
	private String sellerId;
	private String accessKey;
	private String secretKey;

	public Integer getStoreId() {
		return storeId;
	}

	public void setStoreId(Integer storeId) {
		this.storeId = storeId;
	}

	public String getSellerId() {
		return sellerId;
	}

	public void setSellerId(String sellerId) {
		this.sellerId = sellerId;
	}

	public String getAccessKey() {
		return accessKey;
	}

	public void setAccessKey(String accessKey) {
		this.accessKey = accessKey;
	}

	public String getSecretKey() {
		return secretKey;
	}

	public void setSecretKey(String secretKey) {
		this.secretKey = secretKey;
	}
}

[dsyer]

That @ConfigurationProperties looks kind of vanilla. Do you have expensive custom PropertySource implementations (I've seen some pretty crazy ones)?

Unrelated: you mentioned you had some success with a BPP that turns application components into lazy loading proxies, to speed up startup in integration tests. Do you have a version of that you can share?

[tkvangorder]

We do not have any custom property sources in play, just the ones from the config server, the classpath, and system/environment variables.

As for the BPP, I submitted this issue: spring-projects/spring-boot#9685. There is a copy of that post-processor in the issue details.

[tkvangorder]

FYI, I did a local build of 1.3.1-SNAPSHOT:

1.3.0-RELEASE : 35 seconds
1.3.1-SNAPSHOT : 30 seconds.

Your changes around rebinding the parent contexts made a big difference in our application, thank you.

[dsyer]

Thanks for the feedback.

I made a little utility library to print initialization timing data: https://github.com/dsyer/spring-boot-aspectj/tree/50f9061254e093b5c23273adf4d0117b71ee5186/timing. You can get it from repo.spring.io/snapshots (org.springframework.boot.experimental:spring-boot-aspects:1.0.0.BUILD-SNAPSHOT). Run your app with -javaagent:$HOME/.m2/repository/org/aspectj/aspectjweaver/1.8.13/aspectjweaver-1.8.13.jar and this library on the classpath to see the results.

[tkvangorder]

Results:

2018-01-09 11:02:01.473  INFO 20596 --- [           main] o.s.boot.aspects.TimingInterceptor       : Total bind: 3142
2018-01-09 11:02:01.473  INFO 20596 --- [           main] o.s.boot.aspects.TimingInterceptor       : Total init: 12634
2018-01-09 11:02:01.545  INFO 20596 --- [           main] c.b.webservice.WebServiceApplication     : Started WebServiceApplication in 31.971 seconds (JVM running for 32.811)

I cloned your aspectj repo and made some changes to the timing interceptor, which at least for me made it a little easier to parse the timing results.

I am using a Thread Local to keep track of nested "initialization" and then indenting my messages, if you are interested in a PR, I can put one together.

This is what the interceptor looks like with my changes, it's not pretty but works. I am getting what appears to be redundant, nested timing...I couldnt figure out a good way to prune out those "extras".

@Aspect
public class TimingInterceptor {

	private static Log logger = LogFactory.getLog(TimingInterceptor.class);

	private StopWatch bind = new StopWatch("bind");

	private StopWatch init = new StopWatch("init");
	private ThreadLocal<Integer> level = new ThreadLocal<>();

	@Around("execution(private * org.springframework.boot.context.properties.ConfigurationPropertiesBindingPostProcessor.postProcessBeforeInitialization(Object, String, ..)) && args(bean,..)")
	public Object bind(ProceedingJoinPoint joinPoint, Object bean) throws Throwable {
		bind.start();
		Object result = joinPoint.proceed();
		bind.stop();
		long time = bind.getLastTaskTimeMillis();
		if (time > 0) {
			logMessage("Bind        + " + time + "ms : " + bean.getClass().getName());
		}
		return result;
	}

	@Around("execution(* org.springframework.beans.factory.config.BeanPostProcessor+.*(Object, String)) && args(bean,..)")
	public Object post(ProceedingJoinPoint joinPoint, Object bean) throws Throwable {
		long t0 = System.currentTimeMillis();
		Object result = joinPoint.proceed();
		long t1 = System.currentTimeMillis();
		if ((t1 - t0) > 0) { 
			logMessage("Post        + " + (t1 - t0) + "ms : " + joinPoint.getSignature().getDeclaringType().getSimpleName()
					+ "." + joinPoint.getSignature().getName() + ","
					+ bean.getClass().getName());
		}
		return result;
	}

	@Around("execution(* org.springframework.beans.factory.support.AbstractAutowireCapableBeanFactory+.initializeBean(String, Object, ..)) && args(name,bean,..)")
	public Object init(ProceedingJoinPoint joinPoint, String name, Object bean)
			throws Throwable {
		String task = init.currentTaskName();
		if (task != null) {
			init.stop();
		}
		init.start(name);
		int count = level.get() == null?0:level.get();
		count++;
		level.set(count);
		logMessage("Init Start : " + bean.getClass().getName());
		long t0 = System.currentTimeMillis();
		Object result = joinPoint.proceed();
		long t1 = System.currentTimeMillis();
		init.stop();
		if (task != null) {
			init.start(task);
		}
		logMessage("Init End   : " + (t1 - t0) + "ms : " + bean.getClass().getName());
		level.set((count - 1));
		return result;
	}

	private void logMessage(String message) {
		Integer index = level.get();
		if (index == null || index == 0) {
			logger.info(message);
		} else {
			char[] indent = new char[index];
			Arrays.fill(indent, ' ');
			logger.info(new String(indent) + message);
		}		
	}
	
	@EventListener
	public void started(ContextRefreshedEvent event) {
		logger.info("Total bind: " + bind.getTotalTimeMillis());
		logger.info("Total init: " + init.getTotalTimeMillis());
	}
}

And I have put the entire log up on google drive here:

Full Timing log