andreasgal/j2me.js — pull request #312 by mykmelez (2014-09-23 09:33:50+00:00)
Title: profile accurately (fixes #310)

@marco-c There were actually several issues:

1. As I suspected, the VM would count the time spent in a native toward the cost of its caller. Now it calls pause hooks before invoking the native and resume hooks afterward.
2. *Context.start* uses *setZeroTimeout* to yield after each call to VM.execute, and we were counting the time spent yielded, even though it could be spent in a different thread. Now we call pause hooks before setting the timeout and resume hooks afterward.
3. Even with those fixes, sometimes two cost calculations could occur without the start time being reset, effectively double-counting some execution time. For example, *Isolate.\* calls pause hooks, which calculates its cost so far, before invoking a native that invokes *Object.\*, which calls enter hooks with *Isolate.\* as the caller, which also calculates *Isolate.\*'s cost. Now each calculation unsets the start time, and calculations only occur if the start time is set, to avoid every double-counting execution time.

With these fixes, profiles look a lot more reasonable. Here's a top-ten list from a profile generated with this branch (not including a midlet-specific method):

```
406ms 278 com/sun/cldc/i18n/j2me/UTF_8_Writer.write.([CII)V
305ms 10499 java/lang/String.equals.(Ljava/lang/Object;)Z
260ms 12 com/sun/midp/security/DomainPolicy.loadValues.()V
186ms 1053 java/lang/String.hashCode.()I
151ms 1071 java/lang/String.indexOf.(Ljava/lang/String;I)I
144ms 6793 java/io/ByteArrayInputStream.read.()I
138ms 2146 java/lang/StringBuffer.append.(Ljava/lang/String;)Ljava/lang/StringBuffer;
135ms 140 java/io/DataOutputStream.writeUTF.(Ljava/lang/String;Ljava/io/DataOutput;)I
134ms 3150 java/io/ByteArrayOutputStream.write.([BII)V
118ms 5862 java/io/DataInputStream.read.()I
```

And here's the entry for *Connection.existsInternal*:

```
1ms 57 com/ibm/oti/connection/file/Connection.existsInternal.()Z
```