Performance downgrade in the Entity Parser since about a month ago
Activity
Antranig Basman October 5, 2007 at 4:23 PM
Looks like CHM misses are not an issue in 1.5, so the expense is probably a red herring, at least on our platform. It is worth performing tests with other libraries/JVMs though to ensure there is no anomaly.There are places in Sakai where the oswego libraries are still being used though and they should be rooted out. All the same, the optimisation performed above should be enough to stave off any problems, times in the 100s of ns are probably as good as can be achieved.
Antranig Basman October 4, 2007 at 1:39 AM
Optimisation work continuing - first version with Cliff Click:
INFO: Starting large scale reference lookup test... (2007-10-04 09:33:58,031 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Attempted to lookup 100 invalid entities 1000000 times in 437 ms, 0.44 microsecs per entity (2007-10-04 09:33:58,468 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Looked up valid entities 1000000 times in 1203 ms, 1.20 microsecs per entity (2007-10-04 09:33:59,671 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Test completed in 1640 ms, 0.82 microsecs per entity (avg) (2007-10-04 09:33:59,671 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: TESTING LoadTestReferenceLookup: Tests passed : All 2 test(s) passed (2007-10-04 09:33:59,671 main_org.sakaiproject.testrunner.utils.TestRunnerUtils)
Antranig Basman October 3, 2007 at 7:19 PM
The issue appears to be that ConcurrentHashMap lookup misses are ENORMOUSLY more expensive than hits.
It was considered that the extra expense was a single synchronisation lock, but this evidence suggests that
it could well be much more than that (needs further investigation). The code path for parsing unrecognised
references has been optimised to remove the ConcurrentHashMap lookup miss. Commited @rev 36270
Our local testing for raw EntityBroker reference parsing shows the following (Athlon Dual Core 4800+, Windows)
Before optimisation patch:
INFO: Starting large scale reference lookup test... (2007-10-04 02:58:13,281
main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Attempted to lookup 100 invalid entities 100000 times in 297 ms, 2.97
microsecs per entity (2007-10-04 02:58:13,593
main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Looked up valid entities 100000 times in 203 ms, 2.03 microsecs per entity
(2007-10-04 02:58:13,781
main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Test completed in 500 ms, 2.50 microsecs per entity (avg) (2007-10-04
02:58:13,781
main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: TESTING LoadTestReferenceLookup: Tests passed : All 2 test(s) passed
(2007-10-04 02:58:13,781
main_org.sakaiproject.testrunner.utils.TestRunnerUtils)
After optimisation patch:
INFO: Starting large scale reference lookup test... (2007-10-04 03:02:10,609 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Attempted to lookup 100 invalid entities 100000 times in 125 ms, 1.25 microsecs per entity (2007-10-04 03:02:10,734 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Looked up valid entities 100000 times in 187 ms, 1.87 microsecs per entity (2007-10-04 03:02:10,921 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
INFO: Test completed in 312 ms, 1.56 microsecs per entity (avg) (2007-10-04 03:02:10,921 main_org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup)
tests can be run in the entity broker test package https://source.sakaiproject.org/contrib/caret/entitybroker-test/branches/loadtest-props
specific test file is held at org.sakaiproject.entitybrokertest.logic.impl.test.LoadTestReferenceLookup
Ian Boston October 3, 2007 at 11:53 AM
Fixed
Details
Priority
MajorAffects versions
Fix versions
Components
Assignee
Ian BostonIan BostonReporter
Ian BostonIan BostonEnvironment
OSX
Details
Details
Priority
Major
I have noticed a performance downgrade in the EntityManager compared to about a month ago. Is not massive, but it was large enough to show up when profiling for the JCR work which is bad.
The current entity manager relies on each EntityContentProducer rejecting references that are not their own very quickly. In this instance EntityBroker2 has something wrong with it that makes is slower than the rest (approx by 100). Since EntityBroker2 is first in the list, every reference is given to it first time round, and so this has an impact everywhere.
To be fair, there are other parsers that are not that quick and should be looked at.
I have put in a fix that changes the processing of the entity parser to select a likely candidate before trying all in order, so that providing a parser is registered with a root reference have its traffic directed to it.