JAW Speak

Reading time: 4 – 6 minutes

We’re using Spring MVC, configured mostly by annotations, a custom scope for FactoryBeans so they don’t get created once per request, and autowiring by type. This makes for simple code, where the configuration lives right along where it is configured, however after a certain number of autowired beans, performance was abysmal.

Loading the main front page in Firefox, with firebug showing slowness:

Click on to read the full post.

My 8 core box was taking >3000ms to load the /home/ page and after these changes went to <300 ms. (This was in a configuration isolate from any backend service calls or databases – it used stub data, so should be very fast). Before it couldn’t handle over 2 concurrent requests, after we were doing 2 concurrent requests with 70 ms max response times. (Under 300ms for 8-16 concurrent requests).

How did I do this? I discovered it via profiling the app. I was surprised at so much activity in getting the classloader.

Drilling down further, I could see where Spring was calling over and over two slow methods in getBeanNamesForType: isFactoryBean and isTypeMatch.

It is through caching some metadata spring was otherwise recalculating. Every time Spring autowired something, spring iterated over every bean and did reflection to learn it’s type and if it was a factory bean. Spring is very slow when autowiring by type. My colleague (and Spring Batch co-author) Lucas Ward explained SpringSource discouraged autowiring by type until 2.5 came out, and they reversed their position due to the elegant annotation driven web controller configurations. However, you may experience a performance bottleneck. (The only related bug logged that I found was here). I’ve worked with Guice a few years back, and all of this metadata was cached there. I was astonished it wasn’t cached by Spring. I’ll explain how I added my own layer of caching, making an order of magnitude improvement in our system with several hundred beans:

Code:

Here’s the same load under profiling, after adding the caching.

And here it is in firebug:

What were the raw numbers for speedup? I was running apache bench to cause load. Here were before and after results. 2 concurrent requests, 50 requests. ab -t180 -n$NUM_REQ -c$CONCURRENT -r -e $FILE_BASE.csv -g $FILE_BASE.dat http://local.example.com:8080/blah/ > $FILE_BASE.txt

Before:

Server Software:        Apache-Coyote/1.1
Server Hostname:        local.example.com
Server Port:            80

Document Path:          /blah/
Document Length:        123965 bytes

Concurrency Level:      2
Time taken for tests:   89.509 seconds
Complete requests:      50
Failed requests:        49
   (Connect: 0, Receive: 0, Length: 49, Exceptions: 0)
Write errors:           0
Total transferred:      6198170 bytes
HTML transferred:       6177670 bytes
Requests per second:    0.56 [#/sec] (mean)
Time per request:       3580.374 [ms] (mean)
Time per request:       1790.187 [ms] (mean, across all concurrent requests)
Transfer rate:          67.62 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:  3500 3580  50.4   3579    3681
Waiting:     3490 3573  50.6   3571    3675
Total:       3500 3580  50.4   3579    3681

Percentage of the requests served within a certain time (ms)
  50%   3579
  66%   3611
  75%   3614
  80%   3618
  90%   3654
  95%   3668
  98%   3681
  99%   3681
 100%   3681 (longest request)

After:

Server Software:        Apache-Coyote/1.1
Server Hostname:        local.example.com
Server Port:            8080

Document Path:          /blah/
Document Length:        83302 bytes

Concurrency Level:      2
Time taken for tests:   1.141 seconds
Complete requests:      50
Failed requests:        48
   (Connect: 0, Receive: 0, Length: 48, Exceptions: 0)
Write errors:           0
Total transferred:      4184702 bytes
HTML transferred:       4165052 bytes
Requests per second:    43.81 [#/sec] (mean)
Time per request:       45.654 [ms] (mean)
Time per request:       22.827 [ms] (mean, across all concurrent requests)
Transfer rate:          3580.48 [Kbytes/sec] received

Connection Times (ms)
              min  mean[+/-sd] median   max
Connect:        0    0   0.0      0       0
Processing:    40   45   6.3     43      70
Waiting:       38   43   6.3     41      69
Total:         40   45   6.3     43      70

Percentage of the requests served within a certain time (ms)
  50%     43
  66%     44
  75%     45
  80%     48
  90%     54
  95%     55
  98%     70
  99%     70
 100%     70 (longest request)

I didn’t find much else about this for Spring’s slowness in Autowire by type. Please let me know if you find this helpful. Thanks.