Handle profiling buffer underrun.

In rare circumstances it's possible for the thread executing the "stop
profiling" method to start processing the data before all other threads
have finished writing data.  In particular, it's possible for a thread
to be switched out after advancing the offset pointer but before writing
actual data.

This is problematic because the buffer is expected to contain method
pointers.  The fill value (0xee) does not yield a valid pointer.

This adds a short usleep() to reduce the likelihood of the problem
occurring, and adds a buffer scan to detect partial records.  When
encountered, the rest of the log is truncated.

For internal bug 1861898.
diff --git a/vm/Profile.c b/vm/Profile.c
index ca25eb5..ace0dcd 100644
--- a/vm/Profile.c
+++ b/vm/Profile.c
@@ -64,6 +64,8 @@
 #define TRACE_MAGIC         0x574f4c53
 #define TRACE_HEADER_LEN    32
 
+#define FILL_PATTERN        0xeeeeeeee
+
 
 /*
  * Get the wall-clock date/time, in usec.
@@ -358,7 +360,7 @@
         dvmThrowException("Ljava/lang/RuntimeException;", "file open failed");
         goto fail;
     }
-    memset(state->buf, 0xee, bufferSize);
+    memset(state->buf, (char)FILL_PATTERN, bufferSize);
 
     state->bufferSize = bufferSize;
     state->overflow = false;
@@ -412,10 +414,10 @@
  * Run through the data buffer and pull out the methods that were visited.
  * Set a mark so that we know which ones to output.
  */
-static void markTouchedMethods(void)
+static void markTouchedMethods(int endOffset)
 {
     u1* ptr = gDvm.methodTrace.buf + TRACE_HEADER_LEN;
-    u1* end = gDvm.methodTrace.buf + gDvm.methodTrace.curOffset;
+    u1* end = gDvm.methodTrace.buf + endOffset;
     unsigned int methodVal;
     Method* method;
 
@@ -502,13 +504,56 @@
     state->traceEnabled = false;
     MEM_BARRIER();
     sched_yield();
+    usleep(250 * 1000);
 
     if ((state->flags & TRACE_ALLOC_COUNTS) != 0)
         dvmStopAllocCounting();
 
+    /*
+     * It's possible under some circumstances for a thread to have advanced
+     * the data pointer but not written the method value.  It's possible
+     * (though less likely) for the data pointer to be advanced, or partial
+     * data written, while we're doing work here.
+     *
+     * To avoid seeing partially-written data, we grab state->curOffset here,
+     * and use our local copy from here on.  We then scan through what's
+     * already written.  If we see the fill pattern in what should be the
+     * method pointer, we cut things off early.  (If we don't, we'll fail
+     * when we dereference the pointer.)
+     *
+     * There's a theoretical possibility of interrupting another thread
+     * after it has partially written the method pointer, in which case
+     * we'll likely crash when we dereference it.  The possibility of
+     * this actually happening should be at or near zero.  Fixing it
+     * completely could be done by writing the thread number last and
+     * using a sentinel value to indicate a partially-written record,
+     * but that requires memory barriers.
+     */
+    int finalCurOffset = state->curOffset;
+
+    if (finalCurOffset > TRACE_HEADER_LEN) {
+        u4 fillVal = METHOD_ID(FILL_PATTERN);
+        u1* scanPtr = state->buf + TRACE_HEADER_LEN;
+
+        while (scanPtr < state->buf + finalCurOffset) {
+            u4 methodVal = scanPtr[1] | (scanPtr[2] << 8) | (scanPtr[3] << 16)
+                        | (scanPtr[4] << 24);
+            if (METHOD_ID(methodVal) == fillVal) {
+                u1* scanBase = state->buf + TRACE_HEADER_LEN;
+                LOGW("Found unfilled record at %d (of %d)\n",
+                    (scanPtr - scanBase) / TRACE_REC_SIZE,
+                    (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
+                finalCurOffset = scanPtr - state->buf;
+                break;
+            }
+
+            scanPtr += TRACE_REC_SIZE;
+        }
+    }
+
     LOGI("TRACE STOPPED%s: writing %d records\n",
         state->overflow ? " (NOTE: overflowed buffer)" : "",
-        (state->curOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
+        (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
     if (gDvm.debuggerActive) {
         LOGW("WARNING: a debugger is active; method-tracing results "
              "will be skewed\n");
@@ -519,7 +564,7 @@
      */
     u4 clockNsec = getClockOverhead();
 
-    markTouchedMethods();
+    markTouchedMethods(finalCurOffset);
 
     fprintf(state->traceFile, "%cversion\n", TOKEN_CHAR);
     fprintf(state->traceFile, "%d\n", TRACE_VERSION);
@@ -532,7 +577,7 @@
 #endif
     fprintf(state->traceFile, "elapsed-time-usec=%llu\n", elapsed);
     fprintf(state->traceFile, "num-method-calls=%d\n",
-        (state->curOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
+        (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
     fprintf(state->traceFile, "clock-call-overhead-nsec=%d\n", clockNsec);
     fprintf(state->traceFile, "vm=dalvik\n");
     if ((state->flags & TRACE_ALLOC_COUNTS) != 0) {
@@ -549,8 +594,8 @@
     dumpMethodList(state->traceFile);
     fprintf(state->traceFile, "%cend\n", TOKEN_CHAR);
 
-    if (fwrite(state->buf, state->curOffset, 1, state->traceFile) != 1) {
-        LOGE("trace fwrite(%d) failed, errno=%d\n", state->curOffset, errno);
+    if (fwrite(state->buf, finalCurOffset, 1, state->traceFile) != 1) {
+        LOGE("trace fwrite(%d) failed, errno=%d\n", finalCurOffset, errno);
         dvmThrowException("Ljava/lang/RuntimeException;", "data write failed");
         goto bail;
     }