vm/Profile.c

   1 /*
   2  * Copyright (C) 2008 The Android Open Source Project
   3  *
   4  * Licensed under the Apache License, Version 2.0 (the "License");
   5  * you may not use this file except in compliance with the License.
   6  * You may obtain a copy of the License at
   7  *
   8  *      http://www.apache.org/licenses/LICENSE-2.0
   9  *
  10  * Unless required by applicable law or agreed to in writing, software
  11  * distributed under the License is distributed on an "AS IS" BASIS,
  12  * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
  13  * See the License for the specific language governing permissions and
  14  * limitations under the License.
  15  */
  16
  17 /*
  18  * Android's method call profiling goodies.
  19  */
  20 #include "Dalvik.h"
  21
  22 #ifdef WITH_PROFILER        // -- include rest of file
  23
  24 #include <stdlib.h>
  25 #include <stddef.h>
  26 #include <string.h>
  27 #include <sys/time.h>
  28 #include <time.h>
  29 #include <sys/mman.h>
  30 #include <sched.h>
  31 #include <errno.h>
  32 #include <fcntl.h>
  33
  34 #include <cutils/open_memstream.h>
  35
  36 #ifdef HAVE_ANDROID_OS
  37 # define UPDATE_MAGIC_PAGE      1
  38 #endif
  39
  40 /*
  41  * File format:
  42  *  header
  43  *  record 0
  44  *  record 1
  45  *  ...
  46  *
  47  * Header format:
  48  *  u4  magic ('SLOW')
  49  *  u2  version
  50  *  u2  offset to data
  51  *  u8  start date/time in usec
  52  *
  53  * Record format:
  54  *  u1  thread ID
  55  *  u4  method ID | method action
  56  *  u4  time delta since start, in usec
  57  *
  58  * 32 bits of microseconds is 70 minutes.
  59  *
  60  * All values are stored in little-endian order.
  61  */
  62 #define TRACE_REC_SIZE      9
  63 #define TRACE_MAGIC         0x574f4c53
  64 #define TRACE_HEADER_LEN    32
  65
  66 #define FILL_PATTERN        0xeeeeeeee
  67
  68
  69 /*
  70  * Get the wall-clock date/time, in usec.
  71  */
  72 static inline u8 getTimeInUsec()
  73 {
  74     struct timeval tv;
  75
  76     gettimeofday(&tv, NULL);
  77     return tv.tv_sec * 1000000LL + tv.tv_usec;
  78 }
  79
  80 /*
  81  * Get the current time, in microseconds.
  82  *
  83  * This can mean one of two things.  In "global clock" mode, we get the
  84  * same time across all threads.  If we use CLOCK_THREAD_CPUTIME_ID, we
  85  * get a per-thread CPU usage timer.  The latter is better, but a bit
  86  * more complicated to implement.
  87  */
  88 static inline u8 getClock()
  89 {
  90 #if defined(HAVE_POSIX_CLOCKS)
  91     struct timespec tm;
  92
  93     clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tm);
  94     //assert(tm.tv_nsec >= 0 && tm.tv_nsec < 1*1000*1000*1000);
  95     if (!(tm.tv_nsec >= 0 && tm.tv_nsec < 1*1000*1000*1000)) {
  96         LOGE("bad nsec: %ld\n", tm.tv_nsec);
  97         dvmAbort();
  98     }
  99
 100     return tm.tv_sec * 1000000LL + tm.tv_nsec / 1000;
 101 #else
 102     struct timeval tv;
 103
 104     gettimeofday(&tv, NULL);
 105     return tv.tv_sec * 1000000LL + tv.tv_usec;
 106 #endif
 107 }
 108
 109 /*
 110  * Write little-endian data.
 111  */
 112 static inline void storeShortLE(u1* buf, u2 val)
 113 {
 114     *buf++ = (u1) val;
 115     *buf++ = (u1) (val >> 8);
 116 }
 117 static inline void storeIntLE(u1* buf, u4 val)
 118 {
 119     *buf++ = (u1) val;
 120     *buf++ = (u1) (val >> 8);
 121     *buf++ = (u1) (val >> 16);
 122     *buf++ = (u1) (val >> 24);
 123 }
 124 static inline void storeLongLE(u1* buf, u8 val)
 125 {
 126     *buf++ = (u1) val;
 127     *buf++ = (u1) (val >> 8);
 128     *buf++ = (u1) (val >> 16);
 129     *buf++ = (u1) (val >> 24);
 130     *buf++ = (u1) (val >> 32);
 131     *buf++ = (u1) (val >> 40);
 132     *buf++ = (u1) (val >> 48);
 133     *buf++ = (u1) (val >> 56);
 134 }
 135
 136 /*
 137  * Boot-time init.
 138  */
 139 bool dvmProfilingStartup(void)
 140 {
 141     /*
 142      * Initialize "dmtrace" method profiling.
 143      */
 144     memset(&gDvm.methodTrace, 0, sizeof(gDvm.methodTrace));
 145     dvmInitMutex(&gDvm.methodTrace.startStopLock);
 146     pthread_cond_init(&gDvm.methodTrace.threadExitCond, NULL);
 147
 148     ClassObject* clazz =
 149         dvmFindClassNoInit("Ldalvik/system/VMDebug;", NULL);
 150     assert(clazz != NULL);
 151     gDvm.methodTrace.gcMethod =
 152         dvmFindDirectMethodByDescriptor(clazz, "startGC", "()V");
 153     gDvm.methodTrace.classPrepMethod =
 154         dvmFindDirectMethodByDescriptor(clazz, "startClassPrep", "()V");
 155     if (gDvm.methodTrace.gcMethod == NULL ||
 156         gDvm.methodTrace.classPrepMethod == NULL)
 157     {
 158         LOGE("Unable to find startGC or startClassPrep\n");
 159         return false;
 160     }
 161
 162     assert(!dvmCheckException(dvmThreadSelf()));
 163
 164     /*
 165      * Allocate storage for instruction counters.
 166      */
 167     gDvm.executedInstrCounts = (int*) malloc(kNumDalvikInstructions * sizeof(int));
 168     if (gDvm.executedInstrCounts == NULL)
 169         return false;
 170     memset(gDvm.executedInstrCounts, 0, kNumDalvikInstructions * sizeof(int));
 171
 172 #ifdef UPDATE_MAGIC_PAGE
 173     /*
 174      * If we're running on the emulator, there's a magic page into which
 175      * we can put interpreted method information.  This allows interpreted
 176      * methods to show up in the emulator's code traces.
 177      *
 178      * We could key this off of the "ro.kernel.qemu" property, but there's
 179      * no real harm in doing this on a real device.
 180      */
 181     int fd = open("/dev/qemu_trace", O_RDWR);
 182     if (fd < 0) {
 183         LOGV("Unable to open /dev/qemu_trace\n");
 184     } else {
 185         gDvm.emulatorTracePage = mmap(0, SYSTEM_PAGE_SIZE, PROT_READ|PROT_WRITE,
 186                                       MAP_SHARED, fd, 0);
 187         close(fd);
 188         if (gDvm.emulatorTracePage == MAP_FAILED) {
 189             LOGE("Unable to mmap /dev/qemu_trace\n");
 190             gDvm.emulatorTracePage = NULL;
 191         } else {
 192             *(u4*) gDvm.emulatorTracePage = 0;
 193         }
 194     }
 195 #else
 196     assert(gDvm.emulatorTracePage == NULL);
 197 #endif
 198
 199     return true;
 200 }
 201
 202 /*
 203  * Free up profiling resources.
 204  */
 205 void dvmProfilingShutdown(void)
 206 {
 207 #ifdef UPDATE_MAGIC_PAGE
 208     if (gDvm.emulatorTracePage != NULL)
 209         munmap(gDvm.emulatorTracePage, SYSTEM_PAGE_SIZE);
 210 #endif
 211     free(gDvm.executedInstrCounts);
 212 }
 213
 214 /*
 215  * Update the "active profilers" count.
 216  *
 217  * "count" should be +1 or -1.
 218  */
 219 static void updateActiveProfilers(int count)
 220 {
 221     int oldValue, newValue;
 222
 223     do {
 224         oldValue = gDvm.activeProfilers;
 225         newValue = oldValue + count;
 226         if (newValue < 0) {
 227             LOGE("Can't have %d active profilers\n", newValue);
 228             dvmAbort();
 229         }
 230     } while (android_atomic_release_cas(oldValue, newValue,
 231             &gDvm.activeProfilers) != 0);
 232
 233     LOGD("+++ active profiler count now %d\n", newValue);
 234 #if defined(WITH_JIT)
 235     dvmCompilerStateRefresh();
 236 #endif
 237 }
 238
 239
 240 /*
 241  * Reset the "cpuClockBase" field in all threads.
 242  */
 243 static void resetCpuClockBase(void)
 244 {
 245     Thread* thread;
 246
 247     dvmLockThreadList(NULL);
 248     for (thread = gDvm.threadList; thread != NULL; thread = thread->next) {
 249         thread->cpuClockBaseSet = false;
 250         thread->cpuClockBase = 0;
 251     }
 252     dvmUnlockThreadList();
 253 }
 254
 255 /*
 256  * Dump the thread list to the specified file.
 257  */
 258 static void dumpThreadList(FILE* fp)
 259 {
 260     Thread* thread;
 261
 262     dvmLockThreadList(NULL);
 263     for (thread = gDvm.threadList; thread != NULL; thread = thread->next) {
 264         char* name = dvmGetThreadName(thread);
 265
 266         fprintf(fp, "%d\t%s\n", thread->threadId, name);
 267         free(name);
 268     }
 269     dvmUnlockThreadList();
 270 }
 271
 272 /*
 273  * This is a dvmHashForeach callback.
 274  */
 275 static int dumpMarkedMethods(void* vclazz, void* vfp)
 276 {
 277     DexStringCache stringCache;
 278     ClassObject* clazz = (ClassObject*) vclazz;
 279     FILE* fp = (FILE*) vfp;
 280     Method* meth;
 281     char* name;
 282     int i;
 283
 284     dexStringCacheInit(&stringCache);
 285
 286     for (i = 0; i < clazz->virtualMethodCount; i++) {
 287         meth = &clazz->virtualMethods[i];
 288         if (meth->inProfile) {
 289             name = dvmDescriptorToName(meth->clazz->descriptor);
 290             fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
 291                 name, meth->name,
 292                 dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
 293                 dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
 294             meth->inProfile = false;
 295             free(name);
 296         }
 297     }
 298
 299     for (i = 0; i < clazz->directMethodCount; i++) {
 300         meth = &clazz->directMethods[i];
 301         if (meth->inProfile) {
 302             name = dvmDescriptorToName(meth->clazz->descriptor);
 303             fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
 304                 name, meth->name,
 305                 dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
 306                 dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
 307             meth->inProfile = false;
 308             free(name);
 309         }
 310     }
 311
 312     dexStringCacheRelease(&stringCache);
 313
 314     return 0;
 315 }
 316
 317 /*
 318  * Dump the list of "marked" methods to the specified file.
 319  */
 320 static void dumpMethodList(FILE* fp)
 321 {
 322     dvmHashTableLock(gDvm.loadedClasses);
 323     dvmHashForeach(gDvm.loadedClasses, dumpMarkedMethods, (void*) fp);
 324     dvmHashTableUnlock(gDvm.loadedClasses);
 325 }
 326
 327 /*
 328  * Start method tracing.  Method tracing is global to the VM (i.e. we
 329  * trace all threads).
 330  *
 331  * This opens the output file (if an already open fd has not been supplied,
 332  * and we're not going direct to DDMS) and allocates the data buffer.  This
 333  * takes ownership of the file descriptor, closing it on completion.
 334  *
 335  * On failure, we throw an exception and return.
 336  */
 337 void dvmMethodTraceStart(const char* traceFileName, int traceFd, int bufferSize,
 338     int flags, bool directToDdms)
 339 {
 340     MethodTraceState* state = &gDvm.methodTrace;
 341
 342     assert(bufferSize > 0);
 343
 344     dvmLockMutex(&state->startStopLock);
 345     while (state->traceEnabled != 0) {
 346         LOGI("TRACE start requested, but already in progress; stopping\n");
 347         dvmUnlockMutex(&state->startStopLock);
 348         dvmMethodTraceStop();
 349         dvmLockMutex(&state->startStopLock);
 350     }
 351     updateActiveProfilers(1);
 352     LOGI("TRACE STARTED: '%s' %dKB\n", traceFileName, bufferSize / 1024);
 353
 354     /*
 355      * Allocate storage and open files.
 356      *
 357      * We don't need to initialize the buffer, but doing so might remove
 358      * some fault overhead if the pages aren't mapped until touched.
 359      */
 360     state->buf = (u1*) malloc(bufferSize);
 361     if (state->buf == NULL) {
 362         dvmThrowException("Ljava/lang/InternalError;", "buffer alloc failed");
 363         goto fail;
 364     }
 365     if (!directToDdms) {
 366         if (traceFd < 0) {
 367             state->traceFile = fopen(traceFileName, "w");
 368         } else {
 369             state->traceFile = fdopen(traceFd, "w");
 370         }
 371         if (state->traceFile == NULL) {
 372             int err = errno;
 373             LOGE("Unable to open trace file '%s': %s\n",
 374                 traceFileName, strerror(err));
 375             dvmThrowExceptionFmt("Ljava/lang/RuntimeException;",
 376                 "Unable to open trace file '%s': %s",
 377                 traceFileName, strerror(err));
 378             goto fail;
 379         }
 380     }
 381     traceFd = -1;
 382     memset(state->buf, (char)FILL_PATTERN, bufferSize);
 383
 384     state->directToDdms = directToDdms;
 385     state->bufferSize = bufferSize;
 386     state->overflow = false;
 387
 388     /*
 389      * Enable alloc counts if we've been requested to do so.
 390      */
 391     state->flags = flags;
 392     if ((flags & TRACE_ALLOC_COUNTS) != 0)
 393         dvmStartAllocCounting();
 394
 395     /* reset our notion of the start time for all CPU threads */
 396     resetCpuClockBase();
 397
 398     state->startWhen = getTimeInUsec();
 399
 400     /*
 401      * Output the header.
 402      */
 403     memset(state->buf, 0, TRACE_HEADER_LEN);
 404     storeIntLE(state->buf + 0, TRACE_MAGIC);
 405     storeShortLE(state->buf + 4, TRACE_VERSION);
 406     storeShortLE(state->buf + 6, TRACE_HEADER_LEN);
 407     storeLongLE(state->buf + 8, state->startWhen);
 408     state->curOffset = TRACE_HEADER_LEN;
 409
 410     ANDROID_MEMBAR_FULL();
 411
 412     /*
 413      * Set the "enabled" flag.  Once we do this, threads will wait to be
 414      * signaled before exiting, so we have to make sure we wake them up.
 415      */
 416     state->traceEnabled = true;
 417     dvmUnlockMutex(&state->startStopLock);
 418     return;
 419
 420 fail:
 421     updateActiveProfilers(-1);
 422     if (state->traceFile != NULL) {
 423         fclose(state->traceFile);
 424         state->traceFile = NULL;
 425     }
 426     if (state->buf != NULL) {
 427         free(state->buf);
 428         state->buf = NULL;
 429     }
 430     if (traceFd >= 0)
 431         close(traceFd);
 432     dvmUnlockMutex(&state->startStopLock);
 433 }
 434
 435 /*
 436  * Run through the data buffer and pull out the methods that were visited.
 437  * Set a mark so that we know which ones to output.
 438  */
 439 static void markTouchedMethods(int endOffset)
 440 {
 441     u1* ptr = gDvm.methodTrace.buf + TRACE_HEADER_LEN;
 442     u1* end = gDvm.methodTrace.buf + endOffset;
 443     unsigned int methodVal;
 444     Method* method;
 445
 446     while (ptr < end) {
 447         methodVal = *(ptr+1) | (*(ptr+2) << 8) | (*(ptr+3) << 16)
 448                     | (*(ptr+4) << 24);
 449         method = (Method*) METHOD_ID(methodVal);
 450
 451         method->inProfile = true;
 452         ptr += TRACE_REC_SIZE;
 453     }
 454 }
 455
 456 /*
 457  * Compute the amount of overhead in a clock call, in nsec.
 458  *
 459  * This value is going to vary depending on what else is going on in the
 460  * system.  When examined across several runs a pattern should emerge.
 461  */
 462 static u4 getClockOverhead(void)
 463 {
 464     u8 calStart, calElapsed;
 465     int i;
 466
 467     calStart = getClock();
 468     for (i = 1000 * 4; i > 0; i--) {
 469         getClock();
 470         getClock();
 471         getClock();
 472         getClock();
 473         getClock();
 474         getClock();
 475         getClock();
 476         getClock();
 477     }
 478
 479     calElapsed = getClock() - calStart;
 480     return (int) (calElapsed / (8*4));
 481 }
 482
 483 /*
 484  * Returns "true" if method tracing is currently active.
 485  */
 486 bool dvmIsMethodTraceActive(void)
 487 {
 488     const MethodTraceState* state = &gDvm.methodTrace;
 489     return state->traceEnabled;
 490 }
 491
 492 /*
 493  * Stop method tracing.  We write the buffer to disk and generate a key
 494  * file so we can interpret it.
 495  */
 496 void dvmMethodTraceStop(void)
 497 {
 498     MethodTraceState* state = &gDvm.methodTrace;
 499     u8 elapsed;
 500
 501     /*
 502      * We need this to prevent somebody from starting a new trace while
 503      * we're in the process of stopping the old.
 504      */
 505     dvmLockMutex(&state->startStopLock);
 506
 507     if (!state->traceEnabled) {
 508         /* somebody already stopped it, or it was never started */
 509         LOGD("TRACE stop requested, but not running\n");
 510         dvmUnlockMutex(&state->startStopLock);
 511         return;
 512     } else {
 513         updateActiveProfilers(-1);
 514     }
 515
 516     /* compute elapsed time */
 517     elapsed = getTimeInUsec() - state->startWhen;
 518
 519     /*
 520      * Globally disable it, and allow other threads to notice.  We want
 521      * to stall here for at least as long as dvmMethodTraceAdd needs
 522      * to finish.  There's no real risk though -- it will take a while to
 523      * write the data to disk, and we don't clear the buffer pointer until
 524      * after that completes.
 525      */
 526     state->traceEnabled = false;
 527     ANDROID_MEMBAR_FULL();
 528     sched_yield();
 529     usleep(250 * 1000);
 530
 531     if ((state->flags & TRACE_ALLOC_COUNTS) != 0)
 532         dvmStopAllocCounting();
 533
 534     /*
 535      * It's possible under some circumstances for a thread to have advanced
 536      * the data pointer but not written the method value.  It's possible
 537      * (though less likely) for the data pointer to be advanced, or partial
 538      * data written, while we're doing work here.
 539      *
 540      * To avoid seeing partially-written data, we grab state->curOffset here,
 541      * and use our local copy from here on.  We then scan through what's
 542      * already written.  If we see the fill pattern in what should be the
 543      * method pointer, we cut things off early.  (If we don't, we'll fail
 544      * when we dereference the pointer.)
 545      *
 546      * There's a theoretical possibility of interrupting another thread
 547      * after it has partially written the method pointer, in which case
 548      * we'll likely crash when we dereference it.  The possibility of
 549      * this actually happening should be at or near zero.  Fixing it
 550      * completely could be done by writing the thread number last and
 551      * using a sentinel value to indicate a partially-written record,
 552      * but that requires memory barriers.
 553      */
 554     int finalCurOffset = state->curOffset;
 555
 556     if (finalCurOffset > TRACE_HEADER_LEN) {
 557         u4 fillVal = METHOD_ID(FILL_PATTERN);
 558         u1* scanPtr = state->buf + TRACE_HEADER_LEN;
 559
 560         while (scanPtr < state->buf + finalCurOffset) {
 561             u4 methodVal = scanPtr[1] | (scanPtr[2] << 8) | (scanPtr[3] << 16)
 562                         | (scanPtr[4] << 24);
 563             if (METHOD_ID(methodVal) == fillVal) {
 564                 u1* scanBase = state->buf + TRACE_HEADER_LEN;
 565                 LOGW("Found unfilled record at %d (of %d)\n",
 566                     (scanPtr - scanBase) / TRACE_REC_SIZE,
 567                     (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
 568                 finalCurOffset = scanPtr - state->buf;
 569                 break;
 570             }
 571
 572             scanPtr += TRACE_REC_SIZE;
 573         }
 574     }
 575
 576     LOGI("TRACE STOPPED%s: writing %d records\n",
 577         state->overflow ? " (NOTE: overflowed buffer)" : "",
 578         (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
 579     if (gDvm.debuggerActive) {
 580         LOGW("WARNING: a debugger is active; method-tracing results "
 581              "will be skewed\n");
 582     }
 583
 584     /*
 585      * Do a quick calibration test to see how expensive our clock call is.
 586      */
 587     u4 clockNsec = getClockOverhead();
 588
 589     markTouchedMethods(finalCurOffset);
 590
 591     char* memStreamPtr;
 592     size_t memStreamSize;
 593     if (state->directToDdms) {
 594         assert(state->traceFile == NULL);
 595         state->traceFile = open_memstream(&memStreamPtr, &memStreamSize);
 596         if (state->traceFile == NULL) {
 597             /* not expected */
 598             LOGE("Unable to open memstream\n");
 599             dvmAbort();
 600         }
 601     }
 602     assert(state->traceFile != NULL);
 603
 604     fprintf(state->traceFile, "%cversion\n", TOKEN_CHAR);
 605     fprintf(state->traceFile, "%d\n", TRACE_VERSION);
 606     fprintf(state->traceFile, "data-file-overflow=%s\n",
 607         state->overflow ? "true" : "false");
 608 #if defined(HAVE_POSIX_CLOCKS)
 609     fprintf(state->traceFile, "clock=thread-cpu\n");
 610 #else
 611     fprintf(state->traceFile, "clock=global\n");
 612 #endif
 613     fprintf(state->traceFile, "elapsed-time-usec=%llu\n", elapsed);
 614     fprintf(state->traceFile, "num-method-calls=%d\n",
 615         (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
 616     fprintf(state->traceFile, "clock-call-overhead-nsec=%d\n", clockNsec);
 617     fprintf(state->traceFile, "vm=dalvik\n");
 618     if ((state->flags & TRACE_ALLOC_COUNTS) != 0) {
 619         fprintf(state->traceFile, "alloc-count=%d\n",
 620             gDvm.allocProf.allocCount);
 621         fprintf(state->traceFile, "alloc-size=%d\n",
 622             gDvm.allocProf.allocSize);
 623         fprintf(state->traceFile, "gc-count=%d\n",
 624             gDvm.allocProf.gcCount);
 625     }
 626     fprintf(state->traceFile, "%cthreads\n", TOKEN_CHAR);
 627     dumpThreadList(state->traceFile);
 628     fprintf(state->traceFile, "%cmethods\n", TOKEN_CHAR);
 629     dumpMethodList(state->traceFile);
 630     fprintf(state->traceFile, "%cend\n", TOKEN_CHAR);
 631
 632     if (state->directToDdms) {
 633         /*
 634          * Data is in two places: memStreamPtr and state->buf.  Send
 635          * the whole thing to DDMS, wrapped in an MPSE packet.
 636          */
 637         fflush(state->traceFile);
 638
 639         struct iovec iov[2];
 640         iov[0].iov_base = memStreamPtr;
 641         iov[0].iov_len = memStreamSize;
 642         iov[1].iov_base = state->buf;
 643         iov[1].iov_len = finalCurOffset;
 644         dvmDbgDdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
 645     } else {
 646         /* append the profiling data */
 647         if (fwrite(state->buf, finalCurOffset, 1, state->traceFile) != 1) {
 648             int err = errno;
 649             LOGE("trace fwrite(%d) failed: %s\n",
 650                 finalCurOffset, strerror(err));
 651             dvmThrowExceptionFmt("Ljava/lang/RuntimeException;",
 652                 "Trace data write failed: %s", strerror(err));
 653         }
 654     }
 655
 656     /* done! */
 657     free(state->buf);
 658     state->buf = NULL;
 659     fclose(state->traceFile);
 660     state->traceFile = NULL;
 661
 662     /* wake any threads that were waiting for profiling to complete */
 663     dvmBroadcastCond(&state->threadExitCond);
 664     dvmUnlockMutex(&state->startStopLock);
 665 }
 666
 667
 668 /*
 669  * We just did something with a method.  Emit a record.
 670  *
 671  * Multiple threads may be banging on this all at once.  We use atomic ops
 672  * rather than mutexes for speed.
 673  */
 674 void dvmMethodTraceAdd(Thread* self, const Method* method, int action)
 675 {
 676     MethodTraceState* state = &gDvm.methodTrace;
 677     u4 clockDiff, methodVal;
 678     int oldOffset, newOffset;
 679     u1* ptr;
 680
 681     /*
 682      * We can only access the per-thread CPU clock from within the
 683      * thread, so we have to initialize the base time on the first use.
 684      * (Looks like pthread_getcpuclockid(thread, &id) will do what we
 685      * want, but it doesn't appear to be defined on the device.)
 686      */
 687     if (!self->cpuClockBaseSet) {
 688         self->cpuClockBase = getClock();
 689         self->cpuClockBaseSet = true;
 690         //LOGI("thread base id=%d 0x%llx\n",
 691         //    self->threadId, self->cpuClockBase);
 692     }
 693
 694     /*
 695      * Advance "curOffset" atomically.
 696      */
 697     do {
 698         oldOffset = state->curOffset;
 699         newOffset = oldOffset + TRACE_REC_SIZE;
 700         if (newOffset > state->bufferSize) {
 701             state->overflow = true;
 702             return;
 703         }
 704     } while (android_atomic_release_cas(oldOffset, newOffset,
 705             &state->curOffset) != 0);
 706
 707     //assert(METHOD_ACTION((u4) method) == 0);
 708
 709     u8 now = getClock();
 710     clockDiff = (u4) (now - self->cpuClockBase);
 711
 712     methodVal = METHOD_COMBINE((u4) method, action);
 713
 714     /*
 715      * Write data into "oldOffset".
 716      */
 717     ptr = state->buf + oldOffset;
 718     *ptr++ = self->threadId;
 719     *ptr++ = (u1) methodVal;
 720     *ptr++ = (u1) (methodVal >> 8);
 721     *ptr++ = (u1) (methodVal >> 16);
 722     *ptr++ = (u1) (methodVal >> 24);
 723     *ptr++ = (u1) clockDiff;
 724     *ptr++ = (u1) (clockDiff >> 8);
 725     *ptr++ = (u1) (clockDiff >> 16);
 726     *ptr++ = (u1) (clockDiff >> 24);
 727 }
 728
 729 /*
 730  * We just did something with a method.  Emit a record by setting a value
 731  * in a magic memory location.
 732  */
 733 void dvmEmitEmulatorTrace(const Method* method, int action)
 734 {
 735 #ifdef UPDATE_MAGIC_PAGE
 736     /*
 737      * We store the address of the Dalvik bytecodes to the memory-mapped
 738      * trace page for normal Java methods.  We also trace calls to native
 739      * functions by storing the address of the native function to the
 740      * trace page.
 741      * Abstract methods don't have any bytecodes, so we don't trace them.
 742      * (Abstract methods are never called, but in Dalvik they can be
 743      * because we do a "late trap" to a native method to generate the
 744      * abstract method exception.)
 745      */
 746     if (dvmIsAbstractMethod(method))
 747         return;
 748
 749     u4* pMagic = (u4*) gDvm.emulatorTracePage;
 750     u4 addr;
 751
 752     if (dvmIsNativeMethod(method)) {
 753         /*
 754          * The "action" parameter is one of:
 755          *   0 = ENTER
 756          *   1 = EXIT
 757          *   2 = UNROLL
 758          * To help the trace tools reconstruct the runtime stack containing
 759          * a mix of Java plus native methods, we add 4 to the action if this
 760          * is a native method.
 761          */
 762         action += 4;
 763
 764         /*
 765          * Get the address of the native function.
 766          * This isn't the right address -- how do I get it?
 767          * Fortunately, the trace tools can get by without the address, but
 768          * it would be nice to fix this.
 769          */
 770          addr = (u4) method->nativeFunc;
 771     } else {
 772         /*
 773          * The dexlist output shows the &DexCode.insns offset value, which
 774          * is offset from the start of the base DEX header. Method.insns
 775          * is the absolute address, effectively offset from the start of
 776          * the optimized DEX header. We either need to return the
 777          * optimized DEX base file address offset by the right amount, or
 778          * take the "real" address and subtract off the size of the
 779          * optimized DEX header.
 780          *
 781          * Would be nice to factor this out at dexlist time, but we can't count
 782          * on having access to the correct optimized DEX file.
 783          */
 784         assert(method->insns != NULL);
 785         const DexOptHeader* pOptHdr = method->clazz->pDvmDex->pDexFile->pOptHeader;
 786         addr = (u4) method->insns - pOptHdr->dexOffset;
 787     }
 788
 789     *(pMagic+action) = addr;
 790     LOGVV("Set %p = 0x%08x (%s.%s)\n",
 791         pMagic+action, addr, method->clazz->descriptor, method->name);
 792 #endif
 793 }
 794
 795 /*
 796  * The GC calls this when it's about to start.  We add a marker to the
 797  * trace output so the tool can exclude the GC cost from the results.
 798  */
 799 void dvmMethodTraceGCBegin(void)
 800 {
 801     TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTrace.gcMethod);
 802 }
 803 void dvmMethodTraceGCEnd(void)
 804 {
 805     TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTrace.gcMethod);
 806 }
 807
 808 /*
 809  * The class loader calls this when it's loading or initializing a class.
 810  */
 811 void dvmMethodTraceClassPrepBegin(void)
 812 {
 813     TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTrace.classPrepMethod);
 814 }
 815 void dvmMethodTraceClassPrepEnd(void)
 816 {
 817     TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTrace.classPrepMethod);
 818 }
 819
 820
 821 /*
 822  * Enable emulator trace info.
 823  */
 824 void dvmEmulatorTraceStart(void)
 825 {
 826     /* If we could not map the emulator trace page, then do not enable tracing */
 827     if (gDvm.emulatorTracePage == NULL)
 828         return;
 829
 830     updateActiveProfilers(1);
 831
 832     /* in theory we should make this an atomic inc; in practice not important */
 833     gDvm.emulatorTraceEnableCount++;
 834     if (gDvm.emulatorTraceEnableCount == 1)
 835         LOGD("--- emulator method traces enabled\n");
 836 }
 837
 838 /*
 839  * Disable emulator trace info.
 840  */
 841 void dvmEmulatorTraceStop(void)
 842 {
 843     if (gDvm.emulatorTraceEnableCount == 0) {
 844         LOGE("ERROR: emulator tracing not enabled\n");
 845         return;
 846     }
 847     updateActiveProfilers(-1);
 848     /* in theory we should make this an atomic inc; in practice not important */
 849     gDvm.emulatorTraceEnableCount--;
 850     if (gDvm.emulatorTraceEnableCount == 0)
 851         LOGD("--- emulator method traces disabled\n");
 852 }
 853
 854
 855 /*
 856  * Start instruction counting.
 857  */
 858 void dvmStartInstructionCounting()
 859 {
 860     updateActiveProfilers(1);
 861     /* in theory we should make this an atomic inc; in practice not important */
 862     gDvm.instructionCountEnableCount++;
 863 }
 864
 865 /*
 866  * Start instruction counting.
 867  */
 868 void dvmStopInstructionCounting()
 869 {
 870     if (gDvm.instructionCountEnableCount == 0) {
 871         LOGE("ERROR: instruction counting not enabled\n");
 872         dvmAbort();
 873     }
 874     updateActiveProfilers(-1);
 875     gDvm.instructionCountEnableCount--;
 876 }
 877
 878
 879 /*
 880  * Start alloc counting.  Note this doesn't affect the "active profilers"
 881  * count, since the interpreter loop is not involved.
 882  */
 883 void dvmStartAllocCounting(void)
 884 {
 885     gDvm.allocProf.enabled = true;
 886 }
 887
 888 /*
 889  * Stop alloc counting.
 890  */
 891 void dvmStopAllocCounting(void)
 892 {
 893     gDvm.allocProf.enabled = false;
 894 }
 895
 896 #endif /*WITH_PROFILER*/