I did some tests and I have quite different results:
Test is performed using JDE 4.6.1 and BB 8900 simulator. doTest method is called from menu item and there is no other thread that might aquire look. I used loop to 100 to obtain some non-zero percent results. _cache is prefilled with 99 different objecs with keys from 1 to 99.
Do you have the same byte-code? I'm not sure that it is possible but doesn't compiler optimize your code by moving synchronization further?
Added:
I have one test I'd like you to perform. Could you add
entry.created = now;
line after
entry.accessed = now;
Will it take as long as the first assignment? Now I think that the issue is cache miss or something like this.
@SergGr: I appreciate your attempt to reproduce the behavior! Here is a screenshot showing the full bytecode as the Profiler shows it:
As you can see, the Profiler is clearly accounting the bulk of the clock ticks to the "lputfield" opcode. 6MM clock ticks for 8900 calls is ~680K ticks/call for "lputfield" alone - I sure hope that this is merely a flaw in the Profiler wrongly attributing where the real time is being spent and not what is really happening inside the simulator's VM, and I really hope this doesn't ever actually happen on real hardware.
SergGr wrote:I have one test I'd like you to perform. Could you add
entry.created = now;
line after
entry.accessed = now;
Will it take as long as the first assignment? Now I think that the issue is cache miss or something like this.
OK, here's what happens:
First assignment takes the bulk of the time, the second one is minimal.
The "cache" object is a LongHashtable of CacheEntry objects that has been stored and retrieved from PersistentStore and LongCache.get is being invoked by code that is enumerating over the entire hashtable using LongEnumeration ...
I don't think this is a cache miss (seriously, MMU cache miss on BB hardware is THIS slow? no way ...) but maybe VM (virtual memory, not virtual machine) paging in/out from RAM to [wherever].
Ugh ... :-)
