vm/Profile.c

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