EHC ❯ Performance Regression in 1.7 versus 1.6.2

• Type: Bug
• Status: Closed
• Priority: 2 Major
• Resolution: Fixed
• Component/s:
• Labels:

• Assignee: serverteam
• Reporter:
• Created: October 13, 2009
• Votes: 0
• Watchers: 1
• Updated:

  July 27, 2012
• Resolved:

  February 02, 2010

Attachments

• amiller (3.00 k) application/x-csv perfdata.csv
• amiller (3.00 k) application/x-csv perfdata.csv

Description

Gets seems to be affected and maybe puts. Cause unknown.

CacheTest.testConcurrentReadWriteRemoveLFU

1.6.2 INFO: Average Get Time for 5635469 observations: 0.008953292 ms Oct 13, 2009 5:06:36 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Put Time for 206440 obervations: 0.057663243 ms

1.7 INFO: Average Get Time for 5575255 observations: 0.012103124 ms Oct 13, 2009 5:07:02 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Put Time for 36718 obervations: 0.1527044 ms

CacheTest.testConcurrentReadWriteRemoveLRU

1.6.2 Oct 13, 2009 5:12:07 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7428155 observations: 0.008577365 ms Oct 13, 2009 5:12:07 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Put Time for 80873 obervations: 0.06328441 ms

1.7 Oct 13, 2009 5:10:13 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 6796384 observations: 0.011402976 ms Oct 13, 2009 5:10:13 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Put Time for 43118 obervations: 0.0755369 ms

Comments

Alex Miller 2009-10-29

Attached some more runs from 1.6.2 and 1.7.

Alex Miller 2009-10-30

I did some more runs of this on 1.6.2 and 1.7. What I see is that:

a) The values on each test vary significantly (1.6.2 puts: 0.6 to 2.5 and 1.7: 1.1 to 2.9 for example). Enough that I don’t really trust these numbers very far. b) Assuming you believe the numbers, in most cases the 1.7 times are better. put() looks slower in the first two tests but faster in the third. remove[All] looks slower in the first and third test but faster in the second. Given that you added synchronization to put(), I wouldn’t be surprised that it’s slower.
c) The 1.7 runs are showing the concurrency bug from EHC-427 but I think I know the fix for that. Not sure whether that would affect the results - I think it only affects the clear() calls.

In general, I don’t trust these tests enough to really tell me anything specific. If I do believe them, they look mostly better except for *maybe* put, but I expect that to be slower. I don’t think this is worth spending more time on right now.

Alex Miller 2009-10-30

updated perf data - threw out the second run on 1.6.2 as it looked way high and added a new second and third run.

gluck 2009-10-30

I would prefer agreement on this before resolution.

gluck 2009-11-24

Steps to reproduce:

java version “1.6.0_15” Java(TM) SE Runtime Environment (build 1.6.0_15-b03-219) Java HotSpot(TM) 64-Bit Server VM (build 14.1-b02-90, mixed mode)

From IDE run single test:

Nov 24, 2009 9:27:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 4421661 observations: 0.01342889 ms

1.6.2 Nov 24, 2009 9:29:28 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5855218 observations: 0.0076104766 ms

gluck 2009-11-25

Test Environment

Java version “1.6.0_15” Java(TM) SE Runtime Environment (build 1.6.0_15-b03-219) Java HotSpot(TM) 64-Bit Server VM (build 14.1-b02-90, mixed mode)

Nothing running but the IDE. IDE restarted before doing each one.

Test Results

1.7.1-SNAPSHOT Nov 24, 2009 9:27:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 4421661 observations: 0.01342889 ms

Nov 25, 2009 9:47:32 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 6771897 observations: 0.009409476 ms

Nov 25, 2009 9:48:21 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5534771 observations: 0.015619977 ms

Nov 25, 2009 9:48:51 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5473420 observations: 0.010621512 ms

Nov 25, 2009 9:49:19 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5906494 observations: 0.01170576 ms

1.6.2 Nov 24, 2009 9:29:28 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5855218 observations: 0.0076104766 ms

Nov 25, 2009 9:59:50 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7325378 observations: 0.0070990194 ms

Nov 25, 2009 10:00:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7212877 observations: 0.007613883 ms

Nov 25, 2009 10:01:08 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7249593 observations: 0.008791528 ms

Nov 25, 2009 10:04:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7568405 observations: 0.006859041 ms

1.7.x is about 70% slower on this test than 1.6.2

History of this Test

This test has been used as the principal benchmark for ehcache for many years. There may be better tests, but this is the one we have comparative data for.

In 1.5 this test the get time used to be 1.2ms!. i.e. 1200 versus our current .007 in 1.6.2 and .013 in 1.7.x.

The JBoss Cache performance test suite showed a similar speed up, so this test is not rubbish.

/** * <pre> * Orig. * INFO: Average Get Time: 1.2396777 ms * INFO: Average Put Time: 1.4968935 ms * INFO: Average Remove Time: 1.3399061 ms * INFO: Average Remove All Time: 0.22590445 ms * INFO: Average keySet Time: 0.20492058 ms * <p/> * INFO: Average Get Time: 1.081209 ms * INFO: Average Put Time: 1.2307026 ms * INFO: Average Remove Time: 1.1294961 ms * INFO: Average Remove All Time: 0.16385451 ms * INFO: Average keySet Time: 0.1549516 ms * <p/> * CHM version with no sync on get. * INFO: Average Get Time for 2582432 observations: 0.019930825 ms * INFO: Average Put Time for 297 obervations: 41.40404 ms * INFO: Average Remove Time for 1491 obervations: 13.892018 ms * INFO: Average Remove All Time for 135893 observations: 0.54172766 ms * INFO: Average keySet Time for 112686 observations: 0.7157411 ms * <p/> * 1.6 * INFO: Average Get Time for 4984448 observations: 0.006596317 ms * INFO: Average Put Time for 7266 obervations: 0.42361686 ms * INFO: Average Remove Time for 2024066 obervations: 0.012883473 ms * INFO: Average Remove All Time for 3572412 observations: 8.817572E-5 ms * INFO: Average keySet Time for 2653539 observations: 0.002160511 ms * INFO: Total loads: 38 * </pre> * With iterator * 1.6 with 100,000 store size: puts take 45ms. keySet 7ms * 1.6 with 1000,000 store size: puts take 381ms. keySet 7ms * 1,000,000 - using FastRandom (j.u.Random was dog slow) * INFO: Average Get Time for 2065131 observations: 0.013553619 ms * INFO: Average Put Time for 46404 obervations: 0.1605034 ms * INFO: Average Remove Time for 20515 obervations: 0.1515964 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 198 observations: 0.0 ms * <p/> * 9999 - using iterator * INFO: Average Get Time for 4305030 observations: 0.006000423 ms * INFO: Average Put Time for 3216 obervations: 0.92008704 ms * INFO: Average Remove Time for 5294 obervations: 0.048545524 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 147342 observations: 0.5606073 ms * 10001 - using FastRandom * INFO: Average Get Time for 4815249 observations: 0.005541354 ms * INFO: Average Put Time for 5186 obervations: 0.49826455 ms * INFO: Average Remove Time for 129163 obervations: 0.015120429 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 177342 observations: 0.500733 ms * 4999 - using iterator * INFO: Average Get Time for 4317409 observations: 0.0061599445 ms * INFO: Average Put Time for 2708 obervations: 1.0768094 ms * INFO: Average Remove Time for 17664 obervations: 0.11713089 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 321180 observations: 0.26723954 ms * 5001 - using FastRandom * INFO: Average Get Time for 3203904 observations: 0.0053447294 ms * INFO: Average Put Time for 152905 obervations: 0.056616854 ms * INFO: Average Remove Time for 737289 obervations: 0.008854059 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 272898 observations: 0.3118601 ms * * @throws Exception */ @Test public void testConcurrentReadWriteRemoveLFU() throws Exception { testConcurrentReadWriteRemove(MemoryStoreEvictionPolicy.LFU); }

My Concern

I have a number of concerns:

1. This is a real regression. I suspect the extra work being done to collect sampling statistics is the cause.
2. The performance speedup was very hard fought for. I do not want to give it up.

Testing with System.getCurrnentTimeMillis still there but call to liveCacheStatitistics commented out

Nov 25, 2009 10:19:15 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 8030735 observations: 0.00819128 ms

Nov 25, 2009 10:20:18 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 6100940 observations: 0.008779467 ms

Nov 25, 2009 10:20:48 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7782919 observations: 0.008195254 ms

gluck 2009-12-15

Steve

Test Environment

Java version “1.6.0_15” Java(TM) SE Runtime Environment (build 1.6.0_15-b03-219) Java HotSpot(TM) 64-Bit Server VM (build 14.1-b02-90, mixed mode)

Nothing running but the IDE. IDE restarted before doing each one.

Test Results

1.7.1-SNAPSHOT Nov 24, 2009 9:27:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 4421661 observations: 0.01342889 ms

Nov 25, 2009 9:47:32 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 6771897 observations: 0.009409476 ms

Nov 25, 2009 9:48:21 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5534771 observations: 0.015619977 ms

Nov 25, 2009 9:48:51 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5473420 observations: 0.010621512 ms

Nov 25, 2009 9:49:19 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5906494 observations: 0.01170576 ms

1.6.2 Nov 24, 2009 9:29:28 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 5855218 observations: 0.0076104766 ms

Nov 25, 2009 9:59:50 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7325378 observations: 0.0070990194 ms

Nov 25, 2009 10:00:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7212877 observations: 0.007613883 ms

Nov 25, 2009 10:01:08 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7249593 observations: 0.008791528 ms

Nov 25, 2009 10:04:41 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7568405 observations: 0.006859041 ms

1.7.x is about 70% slower on this test than 1.6.2

History of this Test

This test has been used as the principal benchmark for ehcache for many years. There may be better tests, but this is the one we have comparative data for.

In 1.5 this test the get time used to be 1.2ms!. i.e. 1200 versus our current .007 in 1.6.2 and .013 in 1.7.x.

The JBoss Cache performance test suite showed a similar speed up, so this test is not rubbish.

/** * <pre> * Orig. * INFO: Average Get Time: 1.2396777 ms * INFO: Average Put Time: 1.4968935 ms * INFO: Average Remove Time: 1.3399061 ms * INFO: Average Remove All Time: 0.22590445 ms * INFO: Average keySet Time: 0.20492058 ms * <p/> * INFO: Average Get Time: 1.081209 ms * INFO: Average Put Time: 1.2307026 ms * INFO: Average Remove Time: 1.1294961 ms * INFO: Average Remove All Time: 0.16385451 ms * INFO: Average keySet Time: 0.1549516 ms * <p/> * CHM version with no sync on get. * INFO: Average Get Time for 2582432 observations: 0.019930825 ms * INFO: Average Put Time for 297 obervations: 41.40404 ms * INFO: Average Remove Time for 1491 obervations: 13.892018 ms * INFO: Average Remove All Time for 135893 observations: 0.54172766 ms * INFO: Average keySet Time for 112686 observations: 0.7157411 ms * <p/> * 1.6 * INFO: Average Get Time for 4984448 observations: 0.006596317 ms * INFO: Average Put Time for 7266 obervations: 0.42361686 ms * INFO: Average Remove Time for 2024066 obervations: 0.012883473 ms * INFO: Average Remove All Time for 3572412 observations: 8.817572E-5 ms * INFO: Average keySet Time for 2653539 observations: 0.002160511 ms * INFO: Total loads: 38 * </pre> * With iterator * 1.6 with 100,000 store size: puts take 45ms. keySet 7ms * 1.6 with 1000,000 store size: puts take 381ms. keySet 7ms * 1,000,000 - using FastRandom (j.u.Random was dog slow) * INFO: Average Get Time for 2065131 observations: 0.013553619 ms * INFO: Average Put Time for 46404 obervations: 0.1605034 ms * INFO: Average Remove Time for 20515 obervations: 0.1515964 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 198 observations: 0.0 ms * <p/> * 9999 - using iterator * INFO: Average Get Time for 4305030 observations: 0.006000423 ms * INFO: Average Put Time for 3216 obervations: 0.92008704 ms * INFO: Average Remove Time for 5294 obervations: 0.048545524 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 147342 observations: 0.5606073 ms * 10001 - using FastRandom * INFO: Average Get Time for 4815249 observations: 0.005541354 ms * INFO: Average Put Time for 5186 obervations: 0.49826455 ms * INFO: Average Remove Time for 129163 obervations: 0.015120429 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 177342 observations: 0.500733 ms * 4999 - using iterator * INFO: Average Get Time for 4317409 observations: 0.0061599445 ms * INFO: Average Put Time for 2708 obervations: 1.0768094 ms * INFO: Average Remove Time for 17664 obervations: 0.11713089 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 321180 observations: 0.26723954 ms * 5001 - using FastRandom * INFO: Average Get Time for 3203904 observations: 0.0053447294 ms * INFO: Average Put Time for 152905 obervations: 0.056616854 ms * INFO: Average Remove Time for 737289 obervations: 0.008854059 ms * INFO: Average Remove All Time for 0 observations: NaN ms * INFO: Average keySet Time for 272898 observations: 0.3118601 ms * * @throws Exception */ @Test public void testConcurrentReadWriteRemoveLFU() throws Exception { testConcurrentReadWriteRemove(MemoryStoreEvictionPolicy.LFU); }

My Concern

I have a number of concerns:

1. This is a real regression. I suspect the extra work being done to collect sampling statistics is the cause.
2. The performance speedup was very hard fought for. I do not want to give it up.
3. We need to ensure we compare well with competitors. The JBossCache test is the one I have published numbers under. We do not want to be slower than Infinispan etc.
4. We need to remain competitive with roll your own solutions based on CHM

Testing with System.getCurrnentTimeMillis still there but call to liveCacheStatitistics commented out

Nov 25, 2009 10:19:15 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 8030735 observations: 0.00819128 ms

Nov 25, 2009 10:20:18 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 6100940 observations: 0.008779467 ms

Nov 25, 2009 10:20:48 AM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove INFO: Average Get Time for 7782919 observations: 0.008195254 ms

gluck 2009-12-15

One solution might be to skip the new statistics code if monitoring=”off” or autodetect with no Terracotta detected.

gluck 2010-02-02

Statistics can now be turned off with the statistics attribute.

Here is a run after on Ehcache 2.0 snapshot trunk: After turning of statistics.

 * Feb 3, 2010 1:50:32 PM net.sf.ehcache.CacheTest testConcurrentReadWriteRemove
 * INFO: Average Get Time for 7251897 observations: 0.006588345 ms
 * INFO: Average Put Time for 6190 obervations: 0.07479806 ms
 * INFO: Average Remove Time for 4428 obervations: 0.7606143 ms
 * INFO: Average Remove All Time for 5183786 observations: 0.0020039408 ms
 * INFO: Average keySet Time for 4973208 observations: 0.0020630546 ms
 * INFO: Total loadAlls: 189

Regression is now fixed.

gluck 2010-02-02

See previous comment. Fixed.