vm/Profile.c

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