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