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 #include <stdlib.h> 23 #include <stddef.h> 24 #include <string.h> 25 #include <sys/time.h> 26 #include <time.h> 27 #include <sys/mman.h> 28 #include <sched.h> 29 #include <errno.h> 30 #include <fcntl.h> 31 32 #include <cutils/open_memstream.h> 33 34 #ifdef HAVE_ANDROID_OS 35 # define UPDATE_MAGIC_PAGE 1 36 #endif 37 38 /* 39 * File format: 40 * header 41 * record 0 42 * record 1 43 * ... 44 * 45 * Header format: 46 * u4 magic ('SLOW') 47 * u2 version 48 * u2 offset to data 49 * u8 start date/time in usec 50 * 51 * Record format: 52 * u1 thread ID 53 * u4 method ID | method action 54 * u4 time delta since start, in usec 55 * 56 * 32 bits of microseconds is 70 minutes. 57 * 58 * All values are stored in little-endian order. 59 */ 60 #define TRACE_REC_SIZE 9 61 #define TRACE_MAGIC 0x574f4c53 62 #define TRACE_HEADER_LEN 32 63 64 #define FILL_PATTERN 0xeeeeeeee 65 66 67 /* 68 * Get the wall-clock date/time, in usec. 69 */ 70 static inline u8 getTimeInUsec() 71 { 72 struct timeval tv; 73 74 gettimeofday(&tv, NULL); 75 return tv.tv_sec * 1000000LL + tv.tv_usec; 76 } 77 78 /* 79 * Get the current time, in microseconds. 80 * 81 * This can mean one of two things. In "global clock" mode, we get the 82 * same time across all threads. If we use CLOCK_THREAD_CPUTIME_ID, we 83 * get a per-thread CPU usage timer. The latter is better, but a bit 84 * more complicated to implement. 85 */ 86 static inline u8 getClock() 87 { 88 #if defined(HAVE_POSIX_CLOCKS) 89 if (!gDvm.profilerWallClock) { 90 struct timespec tm; 91 92 clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tm); 93 if (!(tm.tv_nsec >= 0 && tm.tv_nsec < 1*1000*1000*1000)) { 94 LOGE("bad nsec: %ld\n", tm.tv_nsec); 95 dvmAbort(); 96 } 97 98 return tm.tv_sec * 1000000LL + tm.tv_nsec / 1000; 99 } else 100 #endif 101 { 102 struct timeval tv; 103 104 gettimeofday(&tv, NULL); 105 return tv.tv_sec * 1000000LL + tv.tv_usec; 106 } 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 if (!gDvm.profilerWallClock) { 608 fprintf(state->traceFile, "clock=thread-cpu\n"); 609 } else 610 #endif 611 { 612 fprintf(state->traceFile, "clock=wall\n"); 613 } 614 fprintf(state->traceFile, "elapsed-time-usec=%llu\n", elapsed); 615 fprintf(state->traceFile, "num-method-calls=%d\n", 616 (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE); 617 fprintf(state->traceFile, "clock-call-overhead-nsec=%d\n", clockNsec); 618 fprintf(state->traceFile, "vm=dalvik\n"); 619 if ((state->flags & TRACE_ALLOC_COUNTS) != 0) { 620 fprintf(state->traceFile, "alloc-count=%d\n", 621 gDvm.allocProf.allocCount); 622 fprintf(state->traceFile, "alloc-size=%d\n", 623 gDvm.allocProf.allocSize); 624 fprintf(state->traceFile, "gc-count=%d\n", 625 gDvm.allocProf.gcCount); 626 } 627 fprintf(state->traceFile, "%cthreads\n", TOKEN_CHAR); 628 dumpThreadList(state->traceFile); 629 fprintf(state->traceFile, "%cmethods\n", TOKEN_CHAR); 630 dumpMethodList(state->traceFile); 631 fprintf(state->traceFile, "%cend\n", TOKEN_CHAR); 632 633 if (state->directToDdms) { 634 /* 635 * Data is in two places: memStreamPtr and state->buf. Send 636 * the whole thing to DDMS, wrapped in an MPSE packet. 637 */ 638 fflush(state->traceFile); 639 640 struct iovec iov[2]; 641 iov[0].iov_base = memStreamPtr; 642 iov[0].iov_len = memStreamSize; 643 iov[1].iov_base = state->buf; 644 iov[1].iov_len = finalCurOffset; 645 dvmDbgDdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2); 646 } else { 647 /* append the profiling data */ 648 if (fwrite(state->buf, finalCurOffset, 1, state->traceFile) != 1) { 649 int err = errno; 650 LOGE("trace fwrite(%d) failed: %s\n", 651 finalCurOffset, strerror(err)); 652 dvmThrowExceptionFmt("Ljava/lang/RuntimeException;", 653 "Trace data write failed: %s", strerror(err)); 654 } 655 } 656 657 /* done! */ 658 free(state->buf); 659 state->buf = NULL; 660 fclose(state->traceFile); 661 state->traceFile = NULL; 662 663 /* wake any threads that were waiting for profiling to complete */ 664 dvmBroadcastCond(&state->threadExitCond); 665 dvmUnlockMutex(&state->startStopLock); 666 } 667 668 669 /* 670 * We just did something with a method. Emit a record. 671 * 672 * Multiple threads may be banging on this all at once. We use atomic ops 673 * rather than mutexes for speed. 674 */ 675 void dvmMethodTraceAdd(Thread* self, const Method* method, int action) 676 { 677 MethodTraceState* state = &gDvm.methodTrace; 678 u4 clockDiff, methodVal; 679 int oldOffset, newOffset; 680 u1* ptr; 681 682 /* 683 * We can only access the per-thread CPU clock from within the 684 * thread, so we have to initialize the base time on the first use. 685 * (Looks like pthread_getcpuclockid(thread, &id) will do what we 686 * want, but it doesn't appear to be defined on the device.) 687 */ 688 if (!self->cpuClockBaseSet) { 689 self->cpuClockBase = getClock(); 690 self->cpuClockBaseSet = true; 691 //LOGI("thread base id=%d 0x%llx\n", 692 // self->threadId, self->cpuClockBase); 693 } 694 695 /* 696 * Advance "curOffset" atomically. 697 */ 698 do { 699 oldOffset = state->curOffset; 700 newOffset = oldOffset + TRACE_REC_SIZE; 701 if (newOffset > state->bufferSize) { 702 state->overflow = true; 703 return; 704 } 705 } while (android_atomic_release_cas(oldOffset, newOffset, 706 &state->curOffset) != 0); 707 708 //assert(METHOD_ACTION((u4) method) == 0); 709 710 u8 now = getClock(); 711 clockDiff = (u4) (now - self->cpuClockBase); 712 713 methodVal = METHOD_COMBINE((u4) method, action); 714 715 /* 716 * Write data into "oldOffset". 717 */ 718 ptr = state->buf + oldOffset; 719 *ptr++ = self->threadId; 720 *ptr++ = (u1) methodVal; 721 *ptr++ = (u1) (methodVal >> 8); 722 *ptr++ = (u1) (methodVal >> 16); 723 *ptr++ = (u1) (methodVal >> 24); 724 *ptr++ = (u1) clockDiff; 725 *ptr++ = (u1) (clockDiff >> 8); 726 *ptr++ = (u1) (clockDiff >> 16); 727 *ptr++ = (u1) (clockDiff >> 24); 728 } 729 730 /* 731 * We just did something with a method. Emit a record by setting a value 732 * in a magic memory location. 733 */ 734 void dvmEmitEmulatorTrace(const Method* method, int action) 735 { 736 #ifdef UPDATE_MAGIC_PAGE 737 /* 738 * We store the address of the Dalvik bytecodes to the memory-mapped 739 * trace page for normal Java methods. We also trace calls to native 740 * functions by storing the address of the native function to the 741 * trace page. 742 * Abstract methods don't have any bytecodes, so we don't trace them. 743 * (Abstract methods are never called, but in Dalvik they can be 744 * because we do a "late trap" to a native method to generate the 745 * abstract method exception.) 746 */ 747 if (dvmIsAbstractMethod(method)) 748 return; 749 750 u4* pMagic = (u4*) gDvm.emulatorTracePage; 751 u4 addr; 752 753 if (dvmIsNativeMethod(method)) { 754 /* 755 * The "action" parameter is one of: 756 * 0 = ENTER 757 * 1 = EXIT 758 * 2 = UNROLL 759 * To help the trace tools reconstruct the runtime stack containing 760 * a mix of Java plus native methods, we add 4 to the action if this 761 * is a native method. 762 */ 763 action += 4; 764 765 /* 766 * Get the address of the native function. 767 * This isn't the right address -- how do I get it? 768 * Fortunately, the trace tools can get by without the address, but 769 * it would be nice to fix this. 770 */ 771 addr = (u4) method->nativeFunc; 772 } else { 773 /* 774 * The dexlist output shows the &DexCode.insns offset value, which 775 * is offset from the start of the base DEX header. Method.insns 776 * is the absolute address, effectively offset from the start of 777 * the optimized DEX header. We either need to return the 778 * optimized DEX base file address offset by the right amount, or 779 * take the "real" address and subtract off the size of the 780 * optimized DEX header. 781 * 782 * Would be nice to factor this out at dexlist time, but we can't count 783 * on having access to the correct optimized DEX file. 784 */ 785 assert(method->insns != NULL); 786 const DexOptHeader* pOptHdr = method->clazz->pDvmDex->pDexFile->pOptHeader; 787 addr = (u4) method->insns - pOptHdr->dexOffset; 788 } 789 790 *(pMagic+action) = addr; 791 LOGVV("Set %p = 0x%08x (%s.%s)\n", 792 pMagic+action, addr, method->clazz->descriptor, method->name); 793 #endif 794 } 795 796 /* 797 * The GC calls this when it's about to start. We add a marker to the 798 * trace output so the tool can exclude the GC cost from the results. 799 */ 800 void dvmMethodTraceGCBegin(void) 801 { 802 TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTrace.gcMethod); 803 } 804 void dvmMethodTraceGCEnd(void) 805 { 806 TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTrace.gcMethod); 807 } 808 809 /* 810 * The class loader calls this when it's loading or initializing a class. 811 */ 812 void dvmMethodTraceClassPrepBegin(void) 813 { 814 TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTrace.classPrepMethod); 815 } 816 void dvmMethodTraceClassPrepEnd(void) 817 { 818 TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTrace.classPrepMethod); 819 } 820 821 822 /* 823 * Enable emulator trace info. 824 */ 825 void dvmEmulatorTraceStart(void) 826 { 827 /* If we could not map the emulator trace page, then do not enable tracing */ 828 if (gDvm.emulatorTracePage == NULL) 829 return; 830 831 updateActiveProfilers(1); 832 833 /* in theory we should make this an atomic inc; in practice not important */ 834 gDvm.emulatorTraceEnableCount++; 835 if (gDvm.emulatorTraceEnableCount == 1) 836 LOGD("--- emulator method traces enabled\n"); 837 } 838 839 /* 840 * Disable emulator trace info. 841 */ 842 void dvmEmulatorTraceStop(void) 843 { 844 if (gDvm.emulatorTraceEnableCount == 0) { 845 LOGE("ERROR: emulator tracing not enabled\n"); 846 return; 847 } 848 updateActiveProfilers(-1); 849 /* in theory we should make this an atomic inc; in practice not important */ 850 gDvm.emulatorTraceEnableCount--; 851 if (gDvm.emulatorTraceEnableCount == 0) 852 LOGD("--- emulator method traces disabled\n"); 853 } 854 855 856 /* 857 * Start instruction counting. 858 */ 859 void dvmStartInstructionCounting() 860 { 861 updateActiveProfilers(1); 862 /* in theory we should make this an atomic inc; in practice not important */ 863 gDvm.instructionCountEnableCount++; 864 } 865 866 /* 867 * Start instruction counting. 868 */ 869 void dvmStopInstructionCounting() 870 { 871 if (gDvm.instructionCountEnableCount == 0) { 872 LOGE("ERROR: instruction counting not enabled\n"); 873 dvmAbort(); 874 } 875 updateActiveProfilers(-1); 876 gDvm.instructionCountEnableCount--; 877 } 878 879 880 /* 881 * Start alloc counting. Note this doesn't affect the "active profilers" 882 * count, since the interpreter loop is not involved. 883 */ 884 void dvmStartAllocCounting(void) 885 { 886 gDvm.allocProf.enabled = true; 887 } 888 889 /* 890 * Stop alloc counting. 891 */ 892 void dvmStopAllocCounting(void) 893 { 894 gDvm.allocProf.enabled = false; 895 } 896