Profile.cpp revision 60fc806b679a3655c228b4093058c59941a49cfe 
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{
254    Thread* thread;
255
256    dvmLockThreadList(NULL);
257    for (thread = gDvm.threadList; thread != NULL; thread = thread->next) {
258        char* name = dvmGetThreadName(thread);
259
260        fprintf(fp, "%d\t%s\n", thread->threadId, name);
261        free(name);
262    }
263    dvmUnlockThreadList();
264}
265
266/*
267 * This is a dvmHashForeach callback.
268 */
269static int dumpMarkedMethods(void* vclazz, void* vfp)
270{
271    DexStringCache stringCache;
272    ClassObject* clazz = (ClassObject*) vclazz;
273    FILE* fp = (FILE*) vfp;
274    Method* meth;
275    char* name;
276    int i;
277
278    dexStringCacheInit(&stringCache);
279
280    for (i = 0; i < clazz->virtualMethodCount; i++) {
281        meth = &clazz->virtualMethods[i];
282        if (meth->inProfile) {
283            name = dvmDescriptorToName(meth->clazz->descriptor);
284            fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
285                name, meth->name,
286                dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
287                dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
288            meth->inProfile = false;
289            free(name);
290        }
291    }
292
293    for (i = 0; i < clazz->directMethodCount; i++) {
294        meth = &clazz->directMethods[i];
295        if (meth->inProfile) {
296            name = dvmDescriptorToName(meth->clazz->descriptor);
297            fprintf(fp, "0x%08x\t%s\t%s\t%s\t%s\t%d\n", (int) meth,
298                name, meth->name,
299                dexProtoGetMethodDescriptor(&meth->prototype, &stringCache),
300                dvmGetMethodSourceFile(meth), dvmLineNumFromPC(meth, 0));
301            meth->inProfile = false;
302            free(name);
303        }
304    }
305
306    dexStringCacheRelease(&stringCache);
307
308    return 0;
309}
310
311/*
312 * Dump the list of "marked" methods to the specified file.
313 */
314static void dumpMethodList(FILE* fp)
315{
316    dvmHashTableLock(gDvm.loadedClasses);
317    dvmHashForeach(gDvm.loadedClasses, dumpMarkedMethods, (void*) fp);
318    dvmHashTableUnlock(gDvm.loadedClasses);
319}
320
321/*
322 * Start method tracing.  Method tracing is global to the VM (i.e. we
323 * trace all threads).
324 *
325 * This opens the output file (if an already open fd has not been supplied,
326 * and we're not going direct to DDMS) and allocates the data buffer.  This
327 * takes ownership of the file descriptor, closing it on completion.
328 *
329 * On failure, we throw an exception and return.
330 */
331void dvmMethodTraceStart(const char* traceFileName, int traceFd, int bufferSize,
332    int flags, bool directToDdms)
333{
334    MethodTraceState* state = &gDvm.methodTrace;
335
336    assert(bufferSize > 0);
337
338    dvmLockMutex(&state->startStopLock);
339    while (state->traceEnabled != 0) {
340        LOGI("TRACE start requested, but already in progress; stopping");
341        dvmUnlockMutex(&state->startStopLock);
342        dvmMethodTraceStop();
343        dvmLockMutex(&state->startStopLock);
344    }
345    /*
346     * ENHANCEMENT: To trace just a single thread, modify the
347     * following to take a Thread* argument, and set the appropriate
348     * interpBreak flags only on the target thread.
349     */
350    updateActiveProfilers(kSubModeMethodTrace, true);
351    LOGI("TRACE STARTED: '%s' %dKB", traceFileName, bufferSize / 1024);
352
353    /*
354     * Allocate storage and open files.
355     *
356     * We don't need to initialize the buffer, but doing so might remove
357     * some fault overhead if the pages aren't mapped until touched.
358     */
359    state->buf = (u1*) malloc(bufferSize);
360    if (state->buf == NULL) {
361        dvmThrowInternalError("buffer alloc failed");
362        goto fail;
363    }
364    if (!directToDdms) {
365        if (traceFd < 0) {
366            state->traceFile = fopen(traceFileName, "w");
367        } else {
368            state->traceFile = fdopen(traceFd, "w");
369        }
370        if (state->traceFile == NULL) {
371            int err = errno;
372            LOGE("Unable to open trace file '%s': %s",
373                traceFileName, strerror(err));
374            dvmThrowExceptionFmt(gDvm.exRuntimeException,
375                "Unable to open trace file '%s': %s",
376                traceFileName, strerror(err));
377            goto fail;
378        }
379    }
380    traceFd = -1;
381    memset(state->buf, (char)FILL_PATTERN, bufferSize);
382
383    state->directToDdms = directToDdms;
384    state->bufferSize = bufferSize;
385    state->overflow = false;
386
387    /*
388     * Enable alloc counts if we've been requested to do so.
389     */
390    state->flags = flags;
391    if ((flags & TRACE_ALLOC_COUNTS) != 0)
392        dvmStartAllocCounting();
393
394    /* reset our notion of the start time for all CPU threads */
395    resetCpuClockBase();
396
397    state->startWhen = getTimeInUsec();
398
399    /*
400     * Output the header.
401     */
402    memset(state->buf, 0, TRACE_HEADER_LEN);
403    storeIntLE(state->buf + 0, TRACE_MAGIC);
404    storeShortLE(state->buf + 4, TRACE_VERSION);
405    storeShortLE(state->buf + 6, TRACE_HEADER_LEN);
406    storeLongLE(state->buf + 8, state->startWhen);
407    state->curOffset = TRACE_HEADER_LEN;
408
409    /*
410     * Set the "enabled" flag.  Once we do this, threads will wait to be
411     * signaled before exiting, so we have to make sure we wake them up.
412     */
413    android_atomic_release_store(true, &state->traceEnabled);
414    dvmUnlockMutex(&state->startStopLock);
415    return;
416
417fail:
418    updateActiveProfilers(kSubModeMethodTrace, false);
419    if (state->traceFile != NULL) {
420        fclose(state->traceFile);
421        state->traceFile = NULL;
422    }
423    if (state->buf != NULL) {
424        free(state->buf);
425        state->buf = NULL;
426    }
427    if (traceFd >= 0)
428        close(traceFd);
429    dvmUnlockMutex(&state->startStopLock);
430}
431
432/*
433 * Run through the data buffer and pull out the methods that were visited.
434 * Set a mark so that we know which ones to output.
435 */
436static void markTouchedMethods(int endOffset)
437{
438    u1* ptr = gDvm.methodTrace.buf + TRACE_HEADER_LEN;
439    u1* end = gDvm.methodTrace.buf + endOffset;
440    unsigned int methodVal;
441    Method* method;
442
443    while (ptr < end) {
444        methodVal = *(ptr+1) | (*(ptr+2) << 8) | (*(ptr+3) << 16)
445                    | (*(ptr+4) << 24);
446        method = (Method*) METHOD_ID(methodVal);
447
448        method->inProfile = true;
449        ptr += TRACE_REC_SIZE;
450    }
451}
452
453/*
454 * Compute the amount of overhead in a clock call, in nsec.
455 *
456 * This value is going to vary depending on what else is going on in the
457 * system.  When examined across several runs a pattern should emerge.
458 */
459static u4 getClockOverhead()
460{
461    u8 calStart, calElapsed;
462    int i;
463
464    calStart = getClock();
465    for (i = 1000 * 4; i > 0; i--) {
466        getClock();
467        getClock();
468        getClock();
469        getClock();
470        getClock();
471        getClock();
472        getClock();
473        getClock();
474    }
475
476    calElapsed = getClock() - calStart;
477    return (int) (calElapsed / (8*4));
478}
479
480/*
481 * Returns "true" if method tracing is currently active.
482 */
483bool dvmIsMethodTraceActive()
484{
485    const MethodTraceState* state = &gDvm.methodTrace;
486    return state->traceEnabled;
487}
488
489/*
490 * Stop method tracing.  We write the buffer to disk and generate a key
491 * file so we can interpret it.
492 */
493void dvmMethodTraceStop()
494{
495    MethodTraceState* state = &gDvm.methodTrace;
496    u8 elapsed;
497
498    /*
499     * We need this to prevent somebody from starting a new trace while
500     * we're in the process of stopping the old.
501     */
502    dvmLockMutex(&state->startStopLock);
503
504    if (!state->traceEnabled) {
505        /* somebody already stopped it, or it was never started */
506        LOGD("TRACE stop requested, but not running");
507        dvmUnlockMutex(&state->startStopLock);
508        return;
509    } else {
510        updateActiveProfilers(kSubModeMethodTrace, false);
511    }
512
513    /* compute elapsed time */
514    elapsed = getTimeInUsec() - state->startWhen;
515
516    /*
517     * Globally disable it, and allow other threads to notice.  We want
518     * to stall here for at least as long as dvmMethodTraceAdd needs
519     * to finish.  There's no real risk though -- it will take a while to
520     * write the data to disk, and we don't clear the buffer pointer until
521     * after that completes.
522     */
523    state->traceEnabled = false;
524    ANDROID_MEMBAR_FULL();
525    sched_yield();
526    usleep(250 * 1000);
527
528    if ((state->flags & TRACE_ALLOC_COUNTS) != 0)
529        dvmStopAllocCounting();
530
531    /*
532     * It's possible under some circumstances for a thread to have advanced
533     * the data pointer but not written the method value.  It's possible
534     * (though less likely) for the data pointer to be advanced, or partial
535     * data written, while we're doing work here.
536     *
537     * To avoid seeing partially-written data, we grab state->curOffset here,
538     * and use our local copy from here on.  We then scan through what's
539     * already written.  If we see the fill pattern in what should be the
540     * method pointer, we cut things off early.  (If we don't, we'll fail
541     * when we dereference the pointer.)
542     *
543     * There's a theoretical possibility of interrupting another thread
544     * after it has partially written the method pointer, in which case
545     * we'll likely crash when we dereference it.  The possibility of
546     * this actually happening should be at or near zero.  Fixing it
547     * completely could be done by writing the thread number last and
548     * using a sentinel value to indicate a partially-written record,
549     * but that requires memory barriers.
550     */
551    int finalCurOffset = state->curOffset;
552
553    if (finalCurOffset > TRACE_HEADER_LEN) {
554        u4 fillVal = METHOD_ID(FILL_PATTERN);
555        u1* scanPtr = state->buf + TRACE_HEADER_LEN;
556
557        while (scanPtr < state->buf + finalCurOffset) {
558            u4 methodVal = scanPtr[1] | (scanPtr[2] << 8) | (scanPtr[3] << 16)
559                        | (scanPtr[4] << 24);
560            if (METHOD_ID(methodVal) == fillVal) {
561                u1* scanBase = state->buf + TRACE_HEADER_LEN;
562                LOGW("Found unfilled record at %d (of %d)",
563                    (scanPtr - scanBase) / TRACE_REC_SIZE,
564                    (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
565                finalCurOffset = scanPtr - state->buf;
566                break;
567            }
568
569            scanPtr += TRACE_REC_SIZE;
570        }
571    }
572
573    LOGI("TRACE STOPPED%s: writing %d records",
574        state->overflow ? " (NOTE: overflowed buffer)" : "",
575        (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
576    if (gDvm.debuggerActive) {
577        LOGW("WARNING: a debugger is active; method-tracing results "
578             "will be skewed\n");
579    }
580
581    /*
582     * Do a quick calibration test to see how expensive our clock call is.
583     */
584    u4 clockNsec = getClockOverhead();
585
586    markTouchedMethods(finalCurOffset);
587
588    char* memStreamPtr;
589    size_t memStreamSize;
590    if (state->directToDdms) {
591        assert(state->traceFile == NULL);
592        state->traceFile = open_memstream(&memStreamPtr, &memStreamSize);
593        if (state->traceFile == NULL) {
594            /* not expected */
595            LOGE("Unable to open memstream");
596            dvmAbort();
597        }
598    }
599    assert(state->traceFile != NULL);
600
601    fprintf(state->traceFile, "%cversion\n", TOKEN_CHAR);
602    fprintf(state->traceFile, "%d\n", TRACE_VERSION);
603    fprintf(state->traceFile, "data-file-overflow=%s\n",
604        state->overflow ? "true" : "false");
605#if defined(HAVE_POSIX_CLOCKS)
606    if (!gDvm.profilerWallClock) {
607        fprintf(state->traceFile, "clock=thread-cpu\n");
608    } else
609#endif
610    {
611        fprintf(state->traceFile, "clock=wall\n");
612    }
613    fprintf(state->traceFile, "elapsed-time-usec=%llu\n", elapsed);
614    fprintf(state->traceFile, "num-method-calls=%d\n",
615        (finalCurOffset - TRACE_HEADER_LEN) / TRACE_REC_SIZE);
616    fprintf(state->traceFile, "clock-call-overhead-nsec=%d\n", clockNsec);
617    fprintf(state->traceFile, "vm=dalvik\n");
618    if ((state->flags & TRACE_ALLOC_COUNTS) != 0) {
619        fprintf(state->traceFile, "alloc-count=%d\n",
620            gDvm.allocProf.allocCount);
621        fprintf(state->traceFile, "alloc-size=%d\n",
622            gDvm.allocProf.allocSize);
623        fprintf(state->traceFile, "gc-count=%d\n",
624            gDvm.allocProf.gcCount);
625    }
626    fprintf(state->traceFile, "%cthreads\n", TOKEN_CHAR);
627    dumpThreadList(state->traceFile);
628    fprintf(state->traceFile, "%cmethods\n", TOKEN_CHAR);
629    dumpMethodList(state->traceFile);
630    fprintf(state->traceFile, "%cend\n", TOKEN_CHAR);
631
632    if (state->directToDdms) {
633        /*
634         * Data is in two places: memStreamPtr and state->buf.  Send
635         * the whole thing to DDMS, wrapped in an MPSE packet.
636         */
637        fflush(state->traceFile);
638
639        struct iovec iov[2];
640        iov[0].iov_base = memStreamPtr;
641        iov[0].iov_len = memStreamSize;
642        iov[1].iov_base = state->buf;
643        iov[1].iov_len = finalCurOffset;
644        dvmDbgDdmSendChunkV(CHUNK_TYPE("MPSE"), iov, 2);
645    } else {
646        /* append the profiling data */
647        if (fwrite(state->buf, finalCurOffset, 1, state->traceFile) != 1) {
648            int err = errno;
649            LOGE("trace fwrite(%d) failed: %s",
650                finalCurOffset, strerror(err));
651            dvmThrowExceptionFmt(gDvm.exRuntimeException,
652                "Trace data write failed: %s", strerror(err));
653        }
654    }
655
656    /* done! */
657    free(state->buf);
658    state->buf = NULL;
659    fclose(state->traceFile);
660    state->traceFile = NULL;
661
662    /* wake any threads that were waiting for profiling to complete */
663    dvmBroadcastCond(&state->threadExitCond);
664    dvmUnlockMutex(&state->startStopLock);
665}
666
667/*
668 * We just did something with a method.  Emit a record.
669 *
670 * Multiple threads may be banging on this all at once.  We use atomic ops
671 * rather than mutexes for speed.
672 */
673void dvmMethodTraceAdd(Thread* self, const Method* method, int action)
674{
675    MethodTraceState* state = &gDvm.methodTrace;
676    u4 clockDiff, methodVal;
677    int oldOffset, newOffset;
678    u1* ptr;
679
680    assert(method != NULL);
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",
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/*
732 * Register the METHOD_TRACE_ENTER action for the fast interpreter and
733 * JIT'ed code.
734 */
735void dvmFastMethodTraceEnter(const Method* method, Thread* self)
736{
737    if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
738        dvmMethodTraceAdd(self, method, METHOD_TRACE_ENTER);
739    }
740}
741
742/*
743 * Register the METHOD_TRACE_EXIT action for the fast interpreter and
744 * JIT'ed code for methods. The about-to-return callee method can be
745 * retrieved from self->interpSave.method.
746 */
747void dvmFastMethodTraceExit(Thread* self)
748{
749    if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
750        dvmMethodTraceAdd(self, self->interpSave.method,
751                          METHOD_TRACE_EXIT);
752    }
753}
754
755/*
756 * Register the METHOD_TRACE_EXIT action for the fast interpreter and
757 * JIT'ed code for JNI methods. The about-to-return JNI callee method is passed
758 * in explicitly.  Also used for inline-execute.
759 */
760void dvmFastNativeMethodTraceExit(const Method* method, Thread* self)
761{
762    if (self->interpBreak.ctl.subMode & kSubModeMethodTrace) {
763        dvmMethodTraceAdd(self, method, METHOD_TRACE_EXIT);
764    }
765}
766
767/*
768 * We just did something with a method.  Emit a record by setting a value
769 * in a magic memory location.
770 */
771void dvmEmitEmulatorTrace(const Method* method, int action)
772{
773#ifdef UPDATE_MAGIC_PAGE
774    /*
775     * We store the address of the Dalvik bytecodes to the memory-mapped
776     * trace page for normal methods.  We also trace calls to native
777     * functions by storing the address of the native function to the
778     * trace page.
779     * Abstract methods don't have any bytecodes, so we don't trace them.
780     * (Abstract methods are never called, but in Dalvik they can be
781     * because we do a "late trap" to a native method to generate the
782     * abstract method exception.)
783     */
784    if (dvmIsAbstractMethod(method))
785        return;
786
787    u4* pMagic = (u4*) gDvm.emulatorTracePage;
788    u4 addr;
789
790    if (dvmIsNativeMethod(method)) {
791        /*
792         * The "action" parameter is one of:
793         *   0 = ENTER
794         *   1 = EXIT
795         *   2 = UNROLL
796         * To help the trace tools reconstruct the runtime stack containing
797         * a mix of normal plus native methods, we add 4 to the action if this
798         * is a native method.
799         */
800        action += 4;
801
802        /*
803         * Get the address of the native function.
804         * This isn't the right address -- how do I get it?
805         * Fortunately, the trace tools can get by without the address, but
806         * it would be nice to fix this.
807         */
808         addr = (u4) method->nativeFunc;
809    } else {
810        /*
811         * The dexlist output shows the &DexCode.insns offset value, which
812         * is offset from the start of the base DEX header. Method.insns
813         * is the absolute address, effectively offset from the start of
814         * the optimized DEX header. We either need to return the
815         * optimized DEX base file address offset by the right amount, or
816         * take the "real" address and subtract off the size of the
817         * optimized DEX header.
818         *
819         * Would be nice to factor this out at dexlist time, but we can't count
820         * on having access to the correct optimized DEX file.
821         */
822        assert(method->insns != NULL);
823        const DexOptHeader* pOptHdr = method->clazz->pDvmDex->pDexFile->pOptHeader;
824        addr = (u4) method->insns - pOptHdr->dexOffset;
825    }
826
827    *(pMagic+action) = addr;
828    LOGVV("Set %p = 0x%08x (%s.%s)",
829        pMagic+action, addr, method->clazz->descriptor, method->name);
830#endif
831}
832
833/*
834 * The GC calls this when it's about to start.  We add a marker to the
835 * trace output so the tool can exclude the GC cost from the results.
836 */
837void dvmMethodTraceGCBegin()
838{
839    TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTraceGcMethod);
840}
841void dvmMethodTraceGCEnd()
842{
843    TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTraceGcMethod);
844}
845
846/*
847 * The class loader calls this when it's loading or initializing a class.
848 */
849void dvmMethodTraceClassPrepBegin()
850{
851    TRACE_METHOD_ENTER(dvmThreadSelf(), gDvm.methodTraceClassPrepMethod);
852}
853void dvmMethodTraceClassPrepEnd()
854{
855    TRACE_METHOD_EXIT(dvmThreadSelf(), gDvm.methodTraceClassPrepMethod);
856}
857
858
859/*
860 * Enable emulator trace info.
861 */
862void dvmEmulatorTraceStart()
863{
864    /* If we could not map the emulator trace page, then do not enable tracing */
865    if (gDvm.emulatorTracePage == NULL)
866        return;
867
868    /* in theory we should make this an atomic inc; in practice not important */
869    gDvm.emulatorTraceEnableCount++;
870    if (gDvm.emulatorTraceEnableCount == 1)
871        LOGD("--- emulator method traces enabled");
872    updateActiveProfilers(kSubModeEmulatorTrace, true);
873}
874
875/*
876 * Disable emulator trace info.
877 */
878void dvmEmulatorTraceStop()
879{
880    if (gDvm.emulatorTraceEnableCount == 0) {
881        LOGE("ERROR: emulator tracing not enabled");
882        return;
883    }
884    /* in theory we should make this an atomic inc; in practice not important */
885    gDvm.emulatorTraceEnableCount--;
886    if (gDvm.emulatorTraceEnableCount == 0)
887        LOGD("--- emulator method traces disabled");
888    updateActiveProfilers(kSubModeEmulatorTrace,
889                          (gDvm.emulatorTraceEnableCount != 0));
890}
891
892
893/*
894 * Start instruction counting.
895 */
896void dvmStartInstructionCounting()
897{
898    /* in theory we should make this an atomic inc; in practice not important */
899    gDvm.instructionCountEnableCount++;
900    updateActiveProfilers(kSubModeInstCounting, true);
901}
902
903/*
904 * Stop instruction counting.
905 */
906void dvmStopInstructionCounting()
907{
908    if (gDvm.instructionCountEnableCount == 0) {
909        LOGE("ERROR: instruction counting not enabled");
910        dvmAbort();
911    }
912    gDvm.instructionCountEnableCount--;
913    updateActiveProfilers(kSubModeInstCounting,
914                          (gDvm.instructionCountEnableCount != 0));
915}
916
917
918/*
919 * Start alloc counting.  Note this doesn't affect the "active profilers"
920 * count, since the interpreter loop is not involved.
921 */
922void dvmStartAllocCounting()
923{
924    gDvm.allocProf.enabled = true;
925}
926
927/*
928 * Stop alloc counting.
929 */
930void dvmStopAllocCounting()
931{
932    gDvm.allocProf.enabled = false;
933}
934