Welcome!

Welcome to the official BlackBerry Support Community Forums.

This is your resource to discuss support topics with your peers, and learn from each other.

inside custom component

Java Development

Reply
Highlighted
New Developer
Posts: 15
Registered: ‎05-13-2008
My Device: Bold 9000, Curve 8310

Is System.currentTimeMilis really this piggy?

So, I've been profiling an application looking for opportunities to speed it up, and have come across something that's really puzzling.  Is System.currentTimeMillis really this slow?

 

Is System.currentTimeMillis really this slow?

 

This is using JDE 4.6.1 and the 8900-4.6.1.109 simulator.  Seriously, why are so many clock ticks being wasted inside System.currentTimeMillis?

 

Is this JDE-specific or simulator-specific?  I'm about to hook up a physical Bold 9000 to the debugger and see if the profiler yields the same sad result, but I've searched the forums and am surprised that no one else has run into this.

 

Thoughts?

Developer
Posts: 19,636
Registered: ‎07-14-2008
My Device: Not Specified

Re: Is System.currentTimeMilis really this piggy?

Is entry.accessed a long?

 

Could you split the line into:

 

long temp = System....

entry.access = temp

 

and tell us what happens?

New Developer
Posts: 15
Registered: ‎05-13-2008
My Device: Bold 9000, Curve 8310

Re: Is System.currentTimeMilis really this piggy?

Yes, entry.accessed is declared "public long accessed" -- do you still want me to introduce the temporary variable?
Developer
Posts: 19,636
Registered: ‎07-14-2008
My Device: Not Specified

Re: Is System.currentTimeMilis really this piggy?

There is no logical reason to split it up, other than to make sure that the time is correctly attributed to the 'get and not the 'update'.  So yes I'd like you to do it, but I don't have a good reason for it!

 

Going to have a play myself in a second, if the signing server is still down.

New Developer
Posts: 15
Registered: ‎05-13-2008
My Device: Bold 9000, Curve 8310

Re: Is System.currentTimeMilis really this piggy?

Okay, this profiling run seems to have behaved totally differently (yay, non-determinism) but interestingly, the "expensive" operation indeed seems to be the assignment to the class member variable, not the call to System.currentTimeMillis itself --

 

 

Like, WTF?  Assigning a long value from local scope to class member taking that many clock ticks?  If this were some bizarre object deep copy I could understand, but this is assignment of a primitive Java type.

 

I so totally hate Java.

New Developer
Posts: 15
Registered: ‎05-13-2008
My Device: Bold 9000, Curve 8310

Re: Is System.currentTimeMilis really this piggy?

Tried profiling the app again, and I get:

 

System.currentTimeMillis.3.png

 

This is just mind-boggling.  Here's the entire definition of the CacheEntry class:

 

 

class CacheEntry implements Persistable { public String key; public Object value; public long created; public long accessed; public CacheEntry(String key, Object value) { this(key, value, System.currentTimeMillis()); } public CacheEntry(String key, Object value, Date created) { this(key, value, created.getTime()); } public CacheEntry(String key, Object value, long created) { this.key = key; this.value = value; this.created = created; this.accessed = created; } }

 

Seriously, is there just something I'm totally messing up?  Is there ANY reasonable explanation for why a primitive Java type value assignment should consume SO many clock ticks, EVER??!
Developer
Posts: 1,415
Registered: ‎07-30-2008
My Device: Not Specified

Re: Is System.currentTimeMilis really this piggy?

Can you post all the yellow code with some context? And, expand the "+" box and see if the that helps at

all- maybe the compiler did something clever with the bytecodes.

First, don't dismiss it as "stuff happens" with profiling. But, with the debugger, there have been times when

it seemed to get threads mixed up ( I suddenly got an array index out of bounds error with a non-sense stack

trace but luckily I knew I had just created one in a different thread and fixing that may the error go away)

and profiling can have even more issues. 

 

I haven't looked at the RIM architecture or profiling tool in much detail but here is a related example. 

Certainly dereferencing could cause cache thrashing on some platforms. Take for example some code

that manipulates a bunch of foo pointers and loads up the faster caches with these

 

foo[] bar

// foo intensive code operating on bar array

// sometimes calls "a"

a(bar[i])

 

void a(foo x)

{

// where in memory is this thing stored? 

// "x" is just some number ( a pointer ) until you try this:

x.member=0;

 

}

 

 

 Also, profilers could be off a line or count spin-wait time and instrumentation on a non-emulated platform

will ( and certainly can on virtual devices ) create artifacts etc. You need to play with it a bit to see what is

relevant.

 

 

 

Developer
Posts: 304
Registered: ‎08-01-2008
My Device: Not Specified

Re: Is System.currentTimeMilis really this piggy?

Try removing the synchronized block and see if changes anything. There might be some locking issue between threads.

 

Also, Is this CacheEntry an inner class of LongCache? If yes, you should have declared it static. That might solve the issue as I guess you are trying to synchronize on the LongCache object.

 

Developer
Posts: 1,415
Registered: ‎07-30-2008
My Device: Not Specified

Re: Is System.currentTimeMilis really this piggy?

System calls often have lots of overhead and may need to wait for locks etc. In the past I've been worried

about glib use of time calls as they are not zero overhead and presumably there is only one clock for

which you could use time waiting or competing with others for access etc. Assuming the assignment is

the real issue however there could be other factors. Indeed,with persistent commits the time

seems to be solely attributed to monitor exit ( leaving sync block ) rather than call to commit.

 

New Developer
Posts: 15
Registered: ‎05-13-2008
My Device: Bold 9000, Curve 8310

Re: Is System.currentTimeMilis really this piggy?

@marchywka: I can start looking into the bytecode that the profiler has instrumented, maybe it'll yield something interesting - good idea.

 

@adwiv: If this was lock contention (caused by the synchronization directive), I would *expect* the majority of time spent on the "synchronized (this)" line -- waiting to acquire the lock, not on the assignment operation inside the critical section.

 

@adwiv: No, LongCache has a LongHashtable whose values are CacheEntry objects.

 

...

 

So, having slept on this problem, I woke up this morning with the question: is this a 32-bit vs. 64-bit issue, especially with the simulator?  Java "long" primitive type is 64-bit, right?

 

I'll keep playing with this but any good suggestions would be really appreciated.