Serving static files slowdown [SPR-16654]

[spring-projects-issues]

Ivan Martos opened SPR-16654 and commented

After we upgraded our project to Spring Boot 2.0.0.RELEASE (that comes with spring-webmc-5.0.4.RELEASE), we experienced major slowdown for serving static files using

org.springframework.web.servlet.config.annotation.WebMvcConfigurer

When we were using Spring Boot 1.5.9.RELEASE average response time for images was about 40ms. After the upgrade it has risen up to average 1400ms.
Code is the same, only thing that changed was spring boot version (with modifications required for update to newer version of spring boot).

After we reverted back to Spring boot 1.5.9 (with spring-webmc-4.3.13.RELEASE) serving static files was once again very fast.
I'm attaching access logs with response times.

---

Affects: 5.0.4

Attachments:

• new-spring-cpu.nps (9.13 kB)
• new-spring-memory.nps (121.10 kB)
• spring_new_access.log (3.34 kB)
• spring_old_access.log (12.34 kB)

0 votes, 5 watchers

[spring-projects-issues]

Rossen Stoyanchev commented

I cannot confirm with the behavior with the spring-mvc-showcase which gives 20-80 ms per resource.

Is this reproducible in a basic sample? What server are you using? How's resource handling configured? Does it matter if Boot is used or not, or if the app is deployed as a war?

[spring-projects-issues]

Ivan Martos commented

In basic example I cant reproduce problem. However I can provide code in which the error is reproducable
inside this commit we reverted back to spring boot 1.5.9
https://github.com/CocktailsGuru/server/commit/9dafb7243f0a223dc61f923ac76dfe12d3a1a7eb
After the revert we got back to 20-80ms per resource
Server - tomcat embedded inside spring boot
Resource handling is configured using WebMvcConfigurer
Boot used or not / war or jar - I haven't tried this options

[spring-projects-issues]

Rossen Stoyanchev commented

The switch from 1.5.9 to 2.0.0 does not narrow it down. That's more than a year's worth of work on the Boot side, even more so on the Spring Framework side. Also I can't see where resources are served from (file system, classpath, ServletContext, other) when you experience the slowdown?

Since you've got the reproducible scenario , can you run a request through a profiler like Yourkit or VisualVM ?

[spring-projects-issues]

Ivan Martos commented

sources are served from file system
I will run request through profiler and get back to you
Thanks

[spring-projects-issues]

Rossen Stoyanchev commented

Anything further?

[spring-projects-issues]

Ivan Martos commented

I'll provide profiling result tomorrow 

[spring-projects-issues]

Ivan Martos commented

Ok, got the profiling results
Heap dump can be found here - https://drive.google.com/open?id=1E3zl5iM1XL9KZC7yOVgH8u2JbRelejza
It the attachments you can find snapshot of CPU ([^new-spring-cpu.nps]) and memory ([^new-spring-memory.nps]) profiling. I've created it using jvisualvm. Sources are jpg files and are served from file system.
Our use case - client requests list of objects (API) and then for each object tries to download image of the object from server. List API has no problem with new spring/spring boot. Problem is only with downloading images. We are downloading simultaneously multiple images, in summary about 100. 

If there is anything further you need from me just let me know
Thanks a lot (and sorry for the delay :) )

[spring-projects-issues]

Rossen Stoyanchev commented

Thanks for the profiling results. The main thing I was looking for is a call tree with total time spent. For that I looked in new-spring-cpu.nps and this is what I found:

1. Total times are heavily skewed. For example for any thread named "https-jsse-nio-8443-exec-??" typically 90-95% of the time is spent in LinkedBlockingQueue under Tomcat's TaskQueue.

2. Drilling into actual request processing time under CoyoteAdapter, i.e. for the remaining 5-10% of the total time, about 90% is in Spring Security's BCrypt, which is intentionally slow,

3. The remaining processing time in Spring MVC is typically quite small, e.g. 100 milliseconds from the 3-4 seconds of overall request processing, and it's usually in different places. One in URL under FileUrlResource, another in I/O writing to the response, yet another in UriTempalte.  

It's a little hard still to make hard conclusions but it looks this may be related to BCrypt. That would apply more widely but maybe it is easier to spot as an outlier with static resource.

So for next steps, try without BCrypt, perhaps  using the standard password encoder that doesn't slow down to confirm if that makes a difference. If it doesn't, take another snapshot to see what methods bubble up this time without BCrypt, and it would also help a lot to trace only in org.springframework related classes to avoid the heavy skewing from Tomcat's TaskQueue.

 

[spring-projects-issues]

Ivan Martos commented

Hi. I wasn't using any bcrypt password, my passwords were in format of "{noop}xxxxxxxx".
However after I've changed my passwords to "xxxxxxxx" (removing noop ID) and added these lines to my configuration:

@Bean
open fun passwordEncoder(): NoOpPasswordEncoder {
    return NoOpPasswordEncoder.getInstance() as NoOpPasswordEncoder
}

Reponse times for images are back at around 100ms. So this works. My hard guess is that something is wrong in DelegatingPasswordEncoder

However now I have a warning about using deprecated NoOpPasswordEncoder

[spring-projects-issues]

Rossen Stoyanchev commented

Okay so it looks like this is related to Spring Security. Rob Winch any comments, or would you suggest to create a ticket under Spring Security?

[spring-projects-issues]

Rob Winch commented

Hi. I wasn't using any bcrypt password, my passwords were in format of "{noop}xxxxxxxx".
However after I've changed my passwords to "xxxxxxxx" (removing noop ID) and added these lines to my configuration:

You may have since changed it, but the results in the profiler indicate that BCrypt was being used at the time of profiling. As Rossen mentions, this is intentionally slow. Can you try profiling again without BCrypt enabled?

[spring-projects-issues]

Rossen Stoyanchev commented

We might as well separate things a bit at this point into two possible issues.

1. We know BCrypt was a factor in the change from 40 to 1400ms, since when it was successfully turned off, it brought response times back to 100. We can't guess whether it is a config issue vs DelegatingPasswordEncoder issue, without more insight into your configuration or a sample, but we know that's a separate issue, and not anything related to the Spring Framework.

2. When you said from 40ms is that an average number and is 100ms also an average. Or is one of those a lower or upper boundary? In other words is there a remaining issue to be investigated aside from the impact of BCrypt. If so let's see another round of snapshots without BCrypt and collecting snapshot data only for the org.springframework package.

As for 1) it might be best to open a separate ticket under Spring Security and describe how you're securing static resources, what you expect, and what you found.

[spring-projects-issues]

Rossen Stoyanchev commented

IvanM any further comments?

[spring-projects-issues]

Ivan Martos commented

yeah, sorry for the delay

Here are sampling results without bcrypt and with editions mentioned above. Sampling is only for org.springframework package.
https://drive.google.com/drive/folders/1akidKrj4xjyAGc5GHEx5UveRTnDyPIpw?usp=sharing

Current code can be found at (branch develop)
https://github.com/CocktailsGuru/server
and commit that "fixed" the issue
https://github.com/CocktailsGuru/server/commit/02049720d328c60621cc0d3d5123baa357afcfda

currently lower boundary is about 60ms and upper about 220ms.  After bypassing BCrypt issue, everything works fine. It seems that the problem is related only to BCrypt.

If there is anything more you need from me just let me know. Or should I rather create separate ticket under Spring Security?

Thanks

[spring-projects-issues]

Rob Winch commented

Thanks for the follow up IvanM 

 

After bypassing BCrypt issue, everything works fine. It seems that the problem is related only to BCrypt.

If there is anything more you need from me just let me know. Or should I rather create separate ticket under Spring Security?

If you are only seeing slowness when using BCrypt, then there is nothing to report. As Rossen mentioned, BCrypt is intentionally resource intensive and thus is deliberately slow. To get better performance you should expect to exchange the long term credential (a username / password) for a short term credential (i.e. a session or a short lived OAuth Token).

[spring-projects-issues]

Rossen Stoyanchev commented

I'm resolving since clearly there is nothing to fix in the Spring Framework.

Feel free to comment further for clarification.

[ahahu]

Possible root cause: spring-projects/spring-security#8498