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