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