vm/Profile.cpp

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