2 * Copyright (C) 2008 The Android Open Source Project
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
8 * http://www.apache.org/licenses/LICENSE-2.0
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.
18 * Android's method call profiling goodies.
21 #include <interp/InterpDefs.h>
33 #include <cutils/open_memstream.h>
35 #ifdef HAVE_ANDROID_OS
36 # define UPDATE_MAGIC_PAGE 1
50 * u8 start date/time in usec
51 * u2 record size in bytes (version >= 2 only)
52 * ... padding to 32 bytes
56 * u4 method ID | method action
57 * u4 time delta since start, in usec
61 * u4 method ID | method action
62 * u4 time delta since start, in usec
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)
70 * 32 bits of microseconds is 70 minutes.
72 * All values are stored in little-endian order.
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
79 #define FILL_PATTERN 0xeeeeeeee
83 * Returns true if the thread CPU clock should be used.
85 static inline bool useThreadCpuClock() {
86 #if defined(HAVE_POSIX_CLOCKS)
87 return gDvm.profilerClockSource != kProfilerClockSourceWall;
94 * Returns true if the wall clock should be used.
96 static inline bool useWallClock() {
97 #if defined(HAVE_POSIX_CLOCKS)
98 return gDvm.profilerClockSource != kProfilerClockSourceThreadCpu;
105 * Get the wall-clock date/time, in usec.
107 static inline u8 getWallTimeInUsec()
111 gettimeofday(&tv, NULL);
112 return tv.tv_sec * 1000000LL + tv.tv_usec;
115 #if defined(HAVE_POSIX_CLOCKS)
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.
121 static inline u8 getThreadCpuTimeInUsec(Thread* thread)
125 pthread_getcpuclockid(thread->handle, &cid);
126 clock_gettime(cid, &tm);
127 if (!(tm.tv_nsec >= 0 && tm.tv_nsec < 1*1000*1000*1000)) {
128 ALOGE("bad nsec: %ld", tm.tv_nsec);
131 return tm.tv_sec * 1000000LL + tm.tv_nsec / 1000;
136 * Get the clock used for stopwatch-like timing measurements on a single thread.
138 static inline u8 getStopwatchClock()
140 #if defined(HAVE_POSIX_CLOCKS)
141 return getThreadCpuTimeInUsec(dvmThreadSelf());
143 return getWallTimeInUsec();
148 * Write little-endian data.
150 static inline void storeShortLE(u1* buf, u2 val)
153 *buf++ = (u1) (val >> 8);
155 static inline void storeIntLE(u1* buf, u4 val)
158 *buf++ = (u1) (val >> 8);
159 *buf++ = (u1) (val >> 16);
160 *buf++ = (u1) (val >> 24);
162 static inline void storeLongLE(u1* buf, u8 val)
165 *buf++ = (u1) (val >> 8);
166 *buf++ = (u1) (val >> 16);
167 *buf++ = (u1) (val >> 24);
168 *buf++ = (u1) (val >> 32);
169 *buf++ = (u1) (val >> 40);
170 *buf++ = (u1) (val >> 48);
171 *buf++ = (u1) (val >> 56);
175 * Gets a thread's stack trace as an array of method pointers of length pCount.
176 * The returned array must be freed by the caller.
178 static const Method** getStackTrace(Thread* thread, size_t* pCount)
180 void* fp = thread->interpSave.curFrame;
181 assert(thread == dvmThreadSelf() || dvmIsSuspended(thread));
183 /* Compute the stack depth. */
184 size_t stackDepth = 0;
186 const StackSaveArea* saveArea = SAVEAREA_FROM_FP(fp);
188 if (!dvmIsBreakFrame((u4*) fp))
191 assert(fp != saveArea->prevFrame);
192 fp = saveArea->prevFrame;
194 *pCount = stackDepth;
197 * Allocate memory for stack trace. This must be freed later, either by
198 * freeThreadStackTraceSamples when tracing stops or by freeThread.
200 const Method** stackTrace = (const Method**) malloc(sizeof(Method*) *
202 if (stackTrace == NULL)
205 /* Walk the stack a second time, filling in the stack trace. */
206 const Method** ptr = stackTrace;
207 fp = thread->interpSave.curFrame;
209 const StackSaveArea* saveArea = SAVEAREA_FROM_FP(fp);
210 const Method* method = saveArea->method;
212 if (!dvmIsBreakFrame((u4*) fp)) {
216 assert(fp != saveArea->prevFrame);
217 fp = saveArea->prevFrame;
219 assert(stackDepth == 0);
224 * Get a sample of the stack trace for a thread.
226 static void getSample(Thread* thread)
228 /* Get old and new stack trace for thread. */
229 size_t newLength = 0;
230 const Method** newStackTrace = getStackTrace(thread, &newLength);
231 size_t oldLength = thread->stackTraceSampleLength;
232 const Method** oldStackTrace = thread->stackTraceSample;
234 /* Read time clocks to use for all events in this trace. */
236 u4 wallClockDiff = 0;
237 dvmMethodTraceReadClocks(thread, &cpuClockDiff, &wallClockDiff);
238 if (oldStackTrace == NULL) {
240 * If there's no previous stack trace sample, log an entry event for
241 * every method in the trace.
243 for (int i = newLength - 1; i >= 0; --i) {
244 dvmMethodTraceAdd(thread, newStackTrace[i], METHOD_TRACE_ENTER,
245 cpuClockDiff, wallClockDiff);
249 * If there's a previous stack trace, diff the traces and emit entry
250 * and exit events accordingly.
252 int diffIndexOld = oldLength - 1;
253 int diffIndexNew = newLength - 1;
254 /* Iterate bottom-up until there's a difference between traces. */
255 while (diffIndexOld >= 0 && diffIndexNew >= 0 &&
256 oldStackTrace[diffIndexOld] == newStackTrace[diffIndexNew]) {
260 /* Iterate top-down over old trace until diff, emitting exit events. */
261 for (int i = 0; i <= diffIndexOld; ++i) {
262 dvmMethodTraceAdd(thread, oldStackTrace[i], METHOD_TRACE_EXIT,
263 cpuClockDiff, wallClockDiff);
265 /* Iterate bottom-up over new trace from diff, emitting entry events. */
266 for (int i = diffIndexNew; i >= 0; --i) {
267 dvmMethodTraceAdd(thread, newStackTrace[i], METHOD_TRACE_ENTER,
268 cpuClockDiff, wallClockDiff);
272 /* Free the old stack trace and update the thread's stack trace sample. */
274 thread->stackTraceSample = newStackTrace;
275 thread->stackTraceSampleLength = newLength;
279 * Entry point for sampling thread. The sampling interval in microseconds is
280 * passed in as an argument.
282 static void* runSamplingThread(void* arg)
284 int intervalUs = (int) arg;
285 while (gDvm.methodTrace.traceEnabled) {
286 dvmSuspendAllThreads(SUSPEND_FOR_SAMPLING);
288 dvmLockThreadList(dvmThreadSelf());
289 for (Thread *thread = gDvm.threadList; thread != NULL; thread = thread->next) {
292 dvmUnlockThreadList();
294 dvmResumeAllThreads(SUSPEND_FOR_SAMPLING);
304 bool dvmProfilingStartup()
307 * Initialize "dmtrace" method profiling.
309 memset(&gDvm.methodTrace, 0, sizeof(gDvm.methodTrace));
310 dvmInitMutex(&gDvm.methodTrace.startStopLock);
311 pthread_cond_init(&gDvm.methodTrace.threadExitCond, NULL);
313 assert(!dvmCheckException(dvmThreadSelf()));
316 * Allocate storage for instruction counters.
318 gDvm.executedInstrCounts = (int*) calloc(kNumPackedOpcodes, sizeof(int));
319 if (gDvm.executedInstrCounts == NULL)
322 #ifdef UPDATE_MAGIC_PAGE
324 * If we're running on the emulator, there's a magic page into which
325 * we can put interpreted method information. This allows interpreted
326 * methods to show up in the emulator's code traces.
328 * We could key this off of the "ro.kernel.qemu" property, but there's
329 * no real harm in doing this on a real device.
331 int fd = open("/dev/qemu_trace", O_RDWR);
333 ALOGV("Unable to open /dev/qemu_trace");
335 gDvm.emulatorTracePage = mmap(0, SYSTEM_PAGE_SIZE, PROT_READ|PROT_WRITE,
338 if (gDvm.emulatorTracePage == MAP_FAILED) {
339 ALOGE("Unable to mmap /dev/qemu_trace");
340 gDvm.emulatorTracePage = NULL;
342 *(u4*) gDvm.emulatorTracePage = 0;
346 assert(gDvm.emulatorTracePage == NULL);
353 * Free up profiling resources.
355 void dvmProfilingShutdown()
357 #ifdef UPDATE_MAGIC_PAGE
358 if (gDvm.emulatorTracePage != NULL)
359 munmap(gDvm.emulatorTracePage, SYSTEM_PAGE_SIZE);
361 free(gDvm.executedInstrCounts);
365 * Update the set of active profilers
367 static void updateActiveProfilers(ExecutionSubModes newMode, bool enable)
369 int oldValue, newValue;
371 // Update global count
373 oldValue = gDvm.activeProfilers;
374 newValue = oldValue + (enable ? 1 : -1);
376 ALOGE("Can't have %d active profilers", newValue);
379 } while (android_atomic_release_cas(oldValue, newValue,
380 &gDvm.activeProfilers) != 0);
384 dvmEnableAllSubMode(newMode);
386 dvmDisableAllSubMode(newMode);
389 #if defined(WITH_JIT)
390 dvmCompilerUpdateGlobalState();
393 ALOGD("+++ active profiler count now %d", newValue);
398 * Reset the "cpuClockBase" field in all threads.
400 static void resetCpuClockBase()
404 dvmLockThreadList(NULL);
405 for (thread = gDvm.threadList; thread != NULL; thread = thread->next) {
406 thread->cpuClockBaseSet = false;
407 thread->cpuClockBase = 0;
409 dvmUnlockThreadList();
413 * Free and reset the "stackTraceSample" field in all threads.
415 static void freeThreadStackTraceSamples()
419 dvmLockThreadList(NULL);
420 for (thread = gDvm.threadList; thread != NULL; thread = thread->next) {
421 free(thread->stackTraceSample);
422 thread->stackTraceSample = NULL;
424 dvmUnlockThreadList();
428 * Dump the thread list to the specified file.
430 static void dumpThreadList(FILE* fp) {
431 dvmLockThreadList(NULL);
432 for (Thread* thread = gDvm.threadList; thread != NULL; thread = thread->next) {
433 std::string threadName(dvmGetThreadName(thread));
434 fprintf(fp, "%d\t%s\n", thread->threadId, threadName.c_str());
436 dvmUnlockThreadList();
440 * This is a dvmHashForeach callback.
442 static int dumpMarkedMethods(void* vclazz, void* vfp)
444 DexStringCache stringCache;
445 ClassObject* clazz = (ClassObject*) vclazz;
446 FILE* fp = (FILE*) vfp;
451 dexStringCacheInit(&stringCache);
453 for (i = 0; i < clazz->virtualMethodCount; i++) {
454 meth = &clazz->virtualMethods[i];
455 if (meth->inProfile) {
456 name = dvmDescriptorToName(meth->clazz->descriptor);
457 fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
459 dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
460 dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
461 meth->inProfile = false;
466 for (i = 0; i < clazz->directMethodCount; i++) {
467 meth = &clazz->directMethods[i];
468 if (meth->inProfile) {
469 name = dvmDescriptorToName(meth->clazz->descriptor);
470 fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
472 dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
473 dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
474 meth->inProfile = false;
479 dexStringCacheRelease(&stringCache);
485 * Dump the list of "marked" methods to the specified file.
487 static void dumpMethodList(FILE* fp)
489 dvmHashTableLock(gDvm.loadedClasses);
490 dvmHashForeach(gDvm.loadedClasses, dumpMarkedMethods, (void*) fp);
491 dvmHashTableUnlock(gDvm.loadedClasses);
495 * Start method tracing. Method tracing is global to the VM (i.e. we
496 * trace all threads).
498 * This opens the output file (if an already open fd has not been supplied,
499 * and we're not going direct to DDMS) and allocates the data buffer. This
500 * takes ownership of the file descriptor, closing it on completion.
502 * On failure, we throw an exception and return.
504 void dvmMethodTraceStart(const char* traceFileName, int traceFd, int bufferSize,
505 int flags, bool directToDdms, bool samplingEnabled, int intervalUs)
507 MethodTraceState* state = &gDvm.methodTrace;
509 assert(bufferSize > 0);
511 dvmLockMutex(&state->startStopLock);
512 while (state->traceEnabled != 0) {
513 ALOGI("TRACE start requested, but already in progress; stopping");
514 dvmUnlockMutex(&state->startStopLock);
515 dvmMethodTraceStop();
516 dvmLockMutex(&state->startStopLock);
518 ALOGI("TRACE STARTED: '%s' %dKB", traceFileName, bufferSize / 1024);
521 * Allocate storage and open files.
523 * We don't need to initialize the buffer, but doing so might remove
524 * some fault overhead if the pages aren't mapped until touched.
526 state->buf = (u1*) malloc(bufferSize);
527 if (state->buf == NULL) {
528 dvmThrowInternalError("buffer alloc failed");
533 state->traceFile = fopen(traceFileName, "w");
535 state->traceFile = fdopen(traceFd, "w");
537 if (state->traceFile == NULL) {
539 ALOGE("Unable to open trace file '%s': %s",
540 traceFileName, strerror(err));
541 dvmThrowExceptionFmt(gDvm.exRuntimeException,
542 "Unable to open trace file '%s': %s",
543 traceFileName, strerror(err));
548 memset(state->buf, (char)FILL_PATTERN, bufferSize);
550 state->directToDdms = directToDdms;
551 state->bufferSize = bufferSize;
552 state->overflow = false;
555 * Enable alloc counts if we've been requested to do so.
557 state->flags = flags;
558 if ((flags & TRACE_ALLOC_COUNTS) != 0)
559 dvmStartAllocCounting();
561 /* reset our notion of the start time for all CPU threads */
564 state->startWhen = getWallTimeInUsec();
566 if (useThreadCpuClock() && useWallClock()) {
567 state->traceVersion = 3;
568 state->recordSize = TRACE_REC_SIZE_DUAL_CLOCK;
570 state->traceVersion = 2;
571 state->recordSize = TRACE_REC_SIZE_SINGLE_CLOCK;
574 state->samplingEnabled = samplingEnabled;
579 memset(state->buf, 0, TRACE_HEADER_LEN);
580 storeIntLE(state->buf + 0, TRACE_MAGIC);
581 storeShortLE(state->buf + 4, state->traceVersion);
582 storeShortLE(state->buf + 6, TRACE_HEADER_LEN);
583 storeLongLE(state->buf + 8, state->startWhen);
584 if (state->traceVersion >= 3) {
585 storeShortLE(state->buf + 16, state->recordSize);
587 state->curOffset = TRACE_HEADER_LEN;
590 * Set the "enabled" flag. Once we do this, threads will wait to be
591 * signaled before exiting, so we have to make sure we wake them up.
593 android_atomic_release_store(true, &state->traceEnabled);
596 * ENHANCEMENT: To trace just a single thread, modify the
597 * following to take a Thread* argument, and set the appropriate
598 * interpBreak flags only on the target thread.
600 if (samplingEnabled) {
601 updateActiveProfilers(kSubModeSampleTrace, true);
602 /* Start the sampling thread. */
603 if (!dvmCreateInternalThread(&state->samplingThreadHandle,
604 "Sampling Thread", &runSamplingThread, (void*) intervalUs)) {
605 dvmThrowInternalError("failed to create sampling thread");
609 updateActiveProfilers(kSubModeMethodTrace, true);
612 dvmUnlockMutex(&state->startStopLock);
616 if (state->traceFile != NULL) {
617 fclose(state->traceFile);
618 state->traceFile = NULL;
620 if (state->buf != NULL) {
626 dvmUnlockMutex(&state->startStopLock);
630 * Run through the data buffer and pull out the methods that were visited.
631 * Set a mark so that we know which ones to output.
633 static void markTouchedMethods(int endOffset)
635 u1* ptr = gDvm.methodTrace.buf + TRACE_HEADER_LEN;
636 u1* end = gDvm.methodTrace.buf + endOffset;
637 size_t recordSize = gDvm.methodTrace.recordSize;
638 unsigned int methodVal;
642 methodVal = ptr[2] | (ptr[3] << 8) | (ptr[4] << 16)
644 method = (Method*) METHOD_ID(methodVal);
646 method->inProfile = true;
652 * Exercises the clocks in the same way they will be during profiling.
654 static inline void measureClockOverhead()
656 #if defined(HAVE_POSIX_CLOCKS)
657 if (useThreadCpuClock()) {
658 getThreadCpuTimeInUsec(dvmThreadSelf());
661 if (useWallClock()) {
667 * Compute the amount of overhead in a clock call, in nsec.
669 * This value is going to vary depending on what else is going on in the
670 * system. When examined across several runs a pattern should emerge.
672 static u4 getClockOverhead()
674 u8 calStart, calElapsed;
677 calStart = getStopwatchClock();
678 for (i = 1000 * 4; i > 0; i--) {
679 measureClockOverhead();
680 measureClockOverhead();
681 measureClockOverhead();
682 measureClockOverhead();
683 measureClockOverhead();
684 measureClockOverhead();
685 measureClockOverhead();
686 measureClockOverhead();
689 calElapsed = getStopwatchClock() - calStart;
690 return (int) (calElapsed / (8*4));
694 * Indicates if method tracing is active and what kind of tracing is active.
696 TracingMode dvmGetMethodTracingMode()
698 const MethodTraceState* state = &gDvm.methodTrace;
699 if (!state->traceEnabled) {
700 return TRACING_INACTIVE;
701 } else if (state->samplingEnabled) {
702 return SAMPLE_PROFILING_ACTIVE;
704 return METHOD_TRACING_ACTIVE;
709 * Stop method tracing. We write the buffer to disk and generate a key
710 * file so we can interpret it.
712 void dvmMethodTraceStop()
714 MethodTraceState* state = &gDvm.methodTrace;
715 bool samplingEnabled = state->samplingEnabled;
719 * We need this to prevent somebody from starting a new trace while
720 * we're in the process of stopping the old.
722 dvmLockMutex(&state->startStopLock);
724 if (!state->traceEnabled) {
725 /* somebody already stopped it, or it was never started */
726 ALOGD("TRACE stop requested, but not running");
727 dvmUnlockMutex(&state->startStopLock);
730 if (samplingEnabled) {
731 updateActiveProfilers(kSubModeSampleTrace, false);
733 updateActiveProfilers(kSubModeMethodTrace, false);
737 /* compute elapsed time */
738 elapsed = getWallTimeInUsec() - state->startWhen;
741 * Globally disable it, and allow other threads to notice. We want
742 * to stall here for at least as long as dvmMethodTraceAdd needs
743 * to finish. There's no real risk though -- it will take a while to
744 * write the data to disk, and we don't clear the buffer pointer until
745 * after that completes.
747 state->traceEnabled = false;
748 ANDROID_MEMBAR_FULL();
752 if ((state->flags & TRACE_ALLOC_COUNTS) != 0)
753 dvmStopAllocCounting();
756 * It's possible under some circumstances for a thread to have advanced
757 * the data pointer but not written the method value. It's possible
758 * (though less likely) for the data pointer to be advanced, or partial
759 * data written, while we're doing work here.
761 * To avoid seeing partially-written data, we grab state->curOffset here,
762 * and use our local copy from here on. We then scan through what's
763 * already written. If we see the fill pattern in what should be the
764 * method pointer, we cut things off early. (If we don't, we'll fail
765 * when we dereference the pointer.)
767 * There's a theoretical possibility of interrupting another thread
768 * after it has partially written the method pointer, in which case
769 * we'll likely crash when we dereference it. The possibility of
770 * this actually happening should be at or near zero. Fixing it
771 * completely could be done by writing the thread number last and
772 * using a sentinel value to indicate a partially-written record,
773 * but that requires memory barriers.
775 int finalCurOffset = state->curOffset;
777 size_t recordSize = state->recordSize;
778 if (finalCurOffset > TRACE_HEADER_LEN) {
779 u4 fillVal = METHOD_ID(FILL_PATTERN);
780 u1* scanPtr = state->buf + TRACE_HEADER_LEN;
782 while (scanPtr < state->buf + finalCurOffset) {
783 u4 methodVal = scanPtr[2] | (scanPtr[3] << 8) | (scanPtr[4] << 16)
784 | (scanPtr[5] << 24);
785 if (METHOD_ID(methodVal) == fillVal) {
786 u1* scanBase = state->buf + TRACE_HEADER_LEN;
787 ALOGW("Found unfilled record at %d (of %d)",
788 (scanPtr - scanBase) / recordSize,
789 (finalCurOffset - TRACE_HEADER_LEN) / recordSize);
790 finalCurOffset = scanPtr - state->buf;
794 scanPtr += recordSize;
798 ALOGI("TRACE STOPPED%s: writing %d records",
799 state->overflow ? " (NOTE: overflowed buffer)" : "",
800 (finalCurOffset - TRACE_HEADER_LEN) / recordSize);
801 if (gDvm.debuggerActive) {
802 ALOGW("WARNING: a debugger is active; method-tracing results "
807 * Do a quick calibration test to see how expensive our clock call is.
809 u4 clockNsec = getClockOverhead();
811 markTouchedMethods(finalCurOffset);
814 size_t memStreamSize;
815 if (state->directToDdms) {
816 assert(state->traceFile == NULL);
817 state->traceFile = open_memstream(&memStreamPtr, &memStreamSize);
818 if (state->traceFile == NULL) {
820 ALOGE("Unable to open memstream");
824 assert(state->traceFile != NULL);
826 fprintf(state->traceFile, "%cversion\n", TOKEN_CHAR);
827 fprintf(state->traceFile, "%d\n", state->traceVersion);
828 fprintf(state->traceFile, "data-file-overflow=%s\n",
829 state->overflow ? "true" : "false");
830 if (useThreadCpuClock()) {
831 if (useWallClock()) {
832 fprintf(state->traceFile, "clock=dual\n");
834 fprintf(state->traceFile, "clock=thread-cpu\n");
837 fprintf(state->traceFile, "clock=wall\n");
839 fprintf(state->traceFile, "elapsed-time-usec=%llu\n", elapsed);
840 fprintf(state->traceFile, "num-method-calls=%d\n",
841 (finalCurOffset - TRACE_HEADER_LEN) / state->recordSize);
842 fprintf(state->traceFile, "clock-call-overhead-nsec=%d\n", clockNsec);
843 fprintf(state->traceFile, "vm=dalvik\n");
844 if ((state->flags & TRACE_ALLOC_COUNTS) != 0) {
845 fprintf(state->traceFile, "alloc-count=%d\n",
846 gDvm.allocProf.allocCount);
847 fprintf(state->traceFile, "alloc-size=%d\n",
848 gDvm.allocProf.allocSize);
849 fprintf(state->traceFile, "gc-count=%d\n",
850 gDvm.allocProf.gcCount);
852 fprintf(state->traceFile, "%cthreads\n", TOKEN_CHAR);
853 dumpThreadList(state->traceFile);
854 fprintf(state->traceFile, "%cmethods\n", TOKEN_CHAR);
855 dumpMethodList(state->traceFile);
856 fprintf(state->traceFile, "%cend\n", TOKEN_CHAR);
858 if (state->directToDdms) {
860 * Data is in two places: memStreamPtr and state->buf. Send
861 * the whole thing to DDMS, wrapped in an MPSE packet.
863 fflush(state->traceFile);
866 iov[0].iov_base = memStreamPtr;
867 iov[0].iov_len = memStreamSize;
868 iov[1].iov_base = state->buf;
869 iov[1].iov_len = finalCurOffset;
870 dvmDbgDdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
872 /* append the profiling data */
873 if (fwrite(state->buf, finalCurOffset, 1, state->traceFile) != 1) {
875 ALOGE("trace fwrite(%d) failed: %s",
876 finalCurOffset, strerror(err));
877 dvmThrowExceptionFmt(gDvm.exRuntimeException,
878 "Trace data write failed: %s", strerror(err));
885 fclose(state->traceFile);
886 state->traceFile = NULL;
888 /* free and clear sampling traces held by all threads */
889 if (samplingEnabled) {
890 freeThreadStackTraceSamples();
893 /* wake any threads that were waiting for profiling to complete */
894 dvmBroadcastCond(&state->threadExitCond);
895 dvmUnlockMutex(&state->startStopLock);
897 /* make sure the sampling thread has stopped */
898 if (samplingEnabled &&
899 pthread_join(state->samplingThreadHandle, NULL) != 0) {
900 ALOGW("Sampling thread join failed");
905 * Read clocks and generate time diffs for method trace events.
907 void dvmMethodTraceReadClocks(Thread* self, u4* cpuClockDiff,
910 #if defined(HAVE_POSIX_CLOCKS)
911 if (useThreadCpuClock()) {
912 if (!self->cpuClockBaseSet) {
913 /* Initialize per-thread CPU clock base time on first use. */
914 self->cpuClockBase = getThreadCpuTimeInUsec(self);
915 self->cpuClockBaseSet = true;
917 *cpuClockDiff = getThreadCpuTimeInUsec(self) - self->cpuClockBase;
921 if (useWallClock()) {
922 *wallClockDiff = getWallTimeInUsec() - gDvm.methodTrace.startWhen;
927 * We just did something with a method. Emit a record.
929 * Multiple threads may be banging on this all at once. We use atomic ops
930 * rather than mutexes for speed.
932 void dvmMethodTraceAdd(Thread* self, const Method* method, int action,
933 u4 cpuClockDiff, u4 wallClockDiff)
935 MethodTraceState* state = &gDvm.methodTrace;
937 int oldOffset, newOffset;
940 assert(method != NULL);
943 * Advance "curOffset" atomically.
946 oldOffset = state->curOffset;
947 newOffset = oldOffset + state->recordSize;
948 if (newOffset > state->bufferSize) {
949 state->overflow = true;
952 } while (android_atomic_release_cas(oldOffset, newOffset,
953 &state->curOffset) != 0);
955 //assert(METHOD_ACTION((u4) method) == 0);
957 methodVal = METHOD_COMBINE((u4) method, action);
960 * Write data into "oldOffset".
962 ptr = state->buf + oldOffset;
963 *ptr++ = (u1) self->threadId;
964 *ptr++ = (u1) (self->threadId >> 8);
965 *ptr++ = (u1) methodVal;
966 *ptr++ = (u1) (methodVal >> 8);
967 *ptr++ = (u1) (methodVal >> 16);
968 *ptr++ = (u1) (methodVal >> 24);
970 #if defined(HAVE_POSIX_CLOCKS)
971 if (useThreadCpuClock()) {
972 *ptr++ = (u1) cpuClockDiff;
973 *ptr++ = (u1) (cpuClockDiff >> 8);
974 *ptr++ = (u1) (cpuClockDiff >> 16);
975 *ptr++ = (u1) (cpuClockDiff >> 24);
979 if (useWallClock()) {
980 *ptr++ = (u1) wallClockDiff;
981 *ptr++ = (u1) (wallClockDiff >> 8);
982 *ptr++ = (u1) (wallClockDiff >> 16);
983 *ptr++ = (u1) (wallClockDiff >> 24);
989 * Register the METHOD_TRACE_ENTER action for the fast interpreter and
992 void dvmFastMethodTraceEnter(const Method* method, Thread* self)
994 if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
996 u4 wallClockDiff = 0;
997 dvmMethodTraceReadClocks(self, &cpuClockDiff, &wallClockDiff);
998 dvmMethodTraceAdd(self, method, METHOD_TRACE_ENTER, cpuClockDiff,
1004 * Register the METHOD_TRACE_EXIT action for the fast interpreter and
1005 * JIT'ed code for methods. The about-to-return callee method can be
1006 * retrieved from self->interpSave.method.
1008 void dvmFastMethodTraceExit(Thread* self)
1010 if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
1011 u4 cpuClockDiff = 0;
1012 u4 wallClockDiff = 0;
1013 dvmMethodTraceReadClocks(self, &cpuClockDiff, &wallClockDiff);
1014 dvmMethodTraceAdd(self, self->interpSave.method,
1015 METHOD_TRACE_EXIT, cpuClockDiff, wallClockDiff);
1020 * Register the METHOD_TRACE_EXIT action for the fast interpreter and
1021 * JIT'ed code for JNI methods. The about-to-return JNI callee method is passed
1022 * in explicitly. Also used for inline-execute.
1024 void dvmFastNativeMethodTraceExit(const Method* method, Thread* self)
1026 if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
1027 u4 cpuClockDiff = 0;
1028 u4 wallClockDiff = 0;
1029 dvmMethodTraceReadClocks(self, &cpuClockDiff, &wallClockDiff);
1030 dvmMethodTraceAdd(self, method, METHOD_TRACE_EXIT, cpuClockDiff,
1036 * We just did something with a method. Emit a record by setting a value
1037 * in a magic memory location.
1039 void dvmEmitEmulatorTrace(const Method* method, int action)
1041 #ifdef UPDATE_MAGIC_PAGE
1043 * We store the address of the Dalvik bytecodes to the memory-mapped
1044 * trace page for normal methods. We also trace calls to native
1045 * functions by storing the address of the native function to the
1047 * Abstract methods don't have any bytecodes, so we don't trace them.
1048 * (Abstract methods are never called, but in Dalvik they can be
1049 * because we do a "late trap" to a native method to generate the
1050 * abstract method exception.)
1052 if (dvmIsAbstractMethod(method))
1055 u4* pMagic = (u4*) gDvm.emulatorTracePage;
1058 if (dvmIsNativeMethod(method)) {
1060 * The "action" parameter is one of:
1064 * To help the trace tools reconstruct the runtime stack containing
1065 * a mix of normal plus native methods, we add 4 to the action if this
1066 * is a native method.
1071 * Get the address of the native function.
1072 * This isn't the right address -- how do I get it?
1073 * Fortunately, the trace tools can get by without the address, but
1074 * it would be nice to fix this.
1076 addr = (u4) method->nativeFunc;
1079 * The dexlist output shows the &DexCode.insns offset value, which
1080 * is offset from the start of the base DEX header. Method.insns
1081 * is the absolute address, effectively offset from the start of
1082 * the optimized DEX header. We either need to return the
1083 * optimized DEX base file address offset by the right amount, or
1084 * take the "real" address and subtract off the size of the
1085 * optimized DEX header.
1087 * Would be nice to factor this out at dexlist time, but we can't count
1088 * on having access to the correct optimized DEX file.
1090 assert(method->insns != NULL);
1091 const DexOptHeader* pOptHdr = method->clazz->pDvmDex->pDexFile->pOptHeader;
1092 addr = (u4) method->insns - pOptHdr->dexOffset;
1095 *(pMagic+action) = addr;
1096 LOGVV("Set %p = 0x%08x (%s.%s)",
1097 pMagic+action, addr, method->clazz->descriptor, method->name);
1102 * The GC calls this when it's about to start. We add a marker to the
1103 * trace output so the tool can exclude the GC cost from the results.
1105 void dvmMethodTraceGCBegin()
1107 TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTraceGcMethod);
1109 void dvmMethodTraceGCEnd()
1111 TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTraceGcMethod);
1115 * The class loader calls this when it's loading or initializing a class.
1117 void dvmMethodTraceClassPrepBegin()
1119 TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTraceClassPrepMethod);
1121 void dvmMethodTraceClassPrepEnd()
1123 TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTraceClassPrepMethod);
1128 * Enable emulator trace info.
1130 void dvmEmulatorTraceStart()
1132 /* If we could not map the emulator trace page, then do not enable tracing */
1133 if (gDvm.emulatorTracePage == NULL)
1136 /* in theory we should make this an atomic inc; in practice not important */
1137 gDvm.emulatorTraceEnableCount++;
1138 if (gDvm.emulatorTraceEnableCount == 1)
1139 ALOGD("--- emulator method traces enabled");
1140 updateActiveProfilers(kSubModeEmulatorTrace, true);
1144 * Disable emulator trace info.
1146 void dvmEmulatorTraceStop()
1148 if (gDvm.emulatorTraceEnableCount == 0) {
1149 ALOGE("ERROR: emulator tracing not enabled");
1152 /* in theory we should make this an atomic inc; in practice not important */
1153 gDvm.emulatorTraceEnableCount--;
1154 if (gDvm.emulatorTraceEnableCount == 0)
1155 ALOGD("--- emulator method traces disabled");
1156 updateActiveProfilers(kSubModeEmulatorTrace,
1157 (gDvm.emulatorTraceEnableCount != 0));
1162 * Start instruction counting.
1164 void dvmStartInstructionCounting()
1166 /* in theory we should make this an atomic inc; in practice not important */
1167 gDvm.instructionCountEnableCount++;
1168 updateActiveProfilers(kSubModeInstCounting, true);
1172 * Stop instruction counting.
1174 void dvmStopInstructionCounting()
1176 if (gDvm.instructionCountEnableCount == 0) {
1177 ALOGE("ERROR: instruction counting not enabled");
1180 gDvm.instructionCountEnableCount--;
1181 updateActiveProfilers(kSubModeInstCounting,
1182 (gDvm.instructionCountEnableCount != 0));
1187 * Start alloc counting. Note this doesn't affect the "active profilers"
1188 * count, since the interpreter loop is not involved.
1190 void dvmStartAllocCounting()
1192 gDvm.allocProf.enabled = true;
1196 * Stop alloc counting.
1198 void dvmStopAllocCounting()
1200 gDvm.allocProf.enabled = false;