ConfigFileApplicationListener logging is very inefficient

[dsyer]

ConfigFileApplicationListener creates a "description" of each resource that it attempts to load. In a tight loop 40% of sampled time goes to just creating the description (and 12% even when there is a single config location). It turns out to be extremely inefficient because of the use of String.format and ResourceUtils.toURI (both are expensive). The description is only logged by default if the file is found, so it isn't even used most of the time. I would recommend just using the "location" instead which is always available and always fairly descriptive of the resource, and costs nothing to compute.

The other main source of inefficiency is ClassPathResource.exists() (25% sampled time). To fix that would be more involved - we'd probably have to index the jars at build time or something. Might be worth it. There's a workaround for users, though - if you know the locations of the config files in the file system, you can skip searching the classpath by specifying spring.config.location explicitly.

[philwebb]

I've also see ClassPathResource.exists() a lot in past profiling adventures.

[dsyer]

Here's another suggestion (it's obvious if you turn up logging to TRACE level): in ConfigFileApplicationListener.Loader.load(String, String, Profile, DocumentFilterFactory, DocumentConsumer) there needs to be a null check for the second loop, i.e:

			if (name != null) {
				for (PropertySourceLoader loader : this.propertySourceLoaders) {
					for (String fileExtension : loader.getFileExtensions()) {
						String prefix = location + name;
						fileExtension = "." + fileExtension;
						loadForFileExtension(loader, prefix, fileExtension, profile,
								filterFactory, consumer);
					}
				}
			}

otherwise we just waste time looking for files called "applicationnull.yml" (etc.).

[dsyer]

Another blip in the flame graph comes from excessive (I believe) use of Binder to bind to profiles.

Here:

			Binder binder = Binder.get(this.environment);
			Set<Profile> activeProfiles = new LinkedHashSet<>();
			activeProfiles.addAll(getProfiles(binder, INCLUDE_PROFILES_PROPERTY));
			activeProfiles.addAll(getProfiles(binder, ACTIVE_PROFILES_PROPERTY));

and here:

				Binder binder = new Binder(
						ConfigurationPropertySources.from(propertySource),
						new PropertySourcesPlaceholdersResolver(this.environment));
				return new Document(propertySource,
						binder.bind("spring.profiles", Bindable.of(String[].class))
								.orElse(null),
						getProfiles(binder, ACTIVE_PROFILES_PROPERTY),
						getProfiles(binder, INCLUDE_PROFILES_PROPERTY));

If I replace these with, respectively,

			Set<Profile> activeProfiles = new LinkedHashSet<>();
			activeProfiles.addAll(getProfiles(ACTIVE_PROFILES_PROPERTY));
			activeProfiles.addAll(getProfiles(INCLUDE_PROFILES_PROPERTY));

and

			String profiles = (String) propertySource.getProperty("spring.profiles");
			return new Document(propertySource, profiles != null
						? StringUtils.commaDelimitedListToStringArray(profiles) : null,
						getProfiles(ACTIVE_PROFILES_PROPERTY),
						getProfiles(INCLUDE_PROFILES_PROPERTY));
			}

where the getProfiles() method is now:

		private Set<Profile> getProfiles(String name) {
			return asProfileSet(asResolvedSet(this.environment.getProperty(name), ""));
		}

then the ConfigFileApplicationListener uses much less CPU sample time on startup (it's only really the calls it makes to EnvironmentPostProcessor that costs anything, once this and the other problems above are addressed).

I didn't test this change other than in a startup benchmark, but it looks functionally identical. The CPU sample time in ConfigFileApplicationListener$Loader.load went down from 3.9% to 2.0%.

[dsyer]

Update: I tried that change in the last comment and some tests fail, so the two versions are not functionally equivalent. Getting rid of the Binder there would be really helpful though, or optimizing the Binder.bind.

[mbhave]

@dsyer Regarding the line below,

ConfigFileApplicationListener creates a "description" of each resource that it attempts to load

Isn't the description created only when TRACE is turned on so it shouldn't be computed in the default case?

[dsyer]

Looks like it was fixed in 1e7ed2f #13512. I suppose there are more possible optimizations: to create the description only once; to not use the resource URL.

[mbhave]

Thanks, Dave. I'd missed that issue.