libs/utils/TimerProbe.cpp

/*
 * Copyright (C) 2008 The Android Open Source Project
 *
 * Licensed under the Apache License, Version 2.0 (the "License");
 * you may not use this file except in compliance with the License.
 * You may obtain a copy of the License at
 *
 *      http://www.apache.org/licenses/LICENSE-2.0
 *
 * Unless required by applicable law or agreed to in writing, software
 * distributed under the License is distributed on an "AS IS" BASIS,
 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
 * See the License for the specific language governing permissions and
 * limitations under the License.
 */

#include <utils/TimerProbe.h>
 
#if ENABLE_TIMER_PROBE

#ifdef LOG_TAG
#undef LOG_TAG
#endif
#define LOG_TAG "time"

namespace android {

Vector<TimerProbe::Bucket> TimerProbe::gBuckets;
TimerProbe* TimerProbe::gExecuteChain;
int TimerProbe::gIndent;
timespec TimerProbe::gRealBase;

TimerProbe::TimerProbe(const char tag[], int* slot) : mTag(tag)
{
    mNext = gExecuteChain;
    gExecuteChain = this;
    mIndent = gIndent;
    gIndent += 1;
    if (mIndent > 0) {
        if (*slot == 0) {
            int count = gBuckets.add();
            *slot = count;
            Bucket& bucket = gBuckets.editItemAt(count);
            memset(&bucket, 0, sizeof(Bucket));
            bucket.mTag = tag;
            bucket.mSlotPtr = slot;
            bucket.mIndent = mIndent;
        }
        mBucket = *slot;
    }
    clock_gettime(CLOCK_REALTIME, &mRealStart);
    if (gRealBase.tv_sec == 0)
        gRealBase = mRealStart;
    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &mPStart);
    clock_gettime(CLOCK_THREAD_CPUTIME_ID, &mTStart);
}

void TimerProbe::end()
{
    timespec realEnd, pEnd, tEnd;
    clock_gettime(CLOCK_REALTIME, &realEnd);
    clock_gettime(CLOCK_PROCESS_CPUTIME_ID, &pEnd);
    clock_gettime(CLOCK_THREAD_CPUTIME_ID, &tEnd);
    print(realEnd, pEnd, tEnd);
    mTag = NULL;
}

TimerProbe::~TimerProbe()
{
    if (mTag != NULL)
        end();
    gExecuteChain = mNext;
    gIndent--;
}


uint32_t TimerProbe::ElapsedTime(const timespec& start, const timespec& end)
{
    int sec = end.tv_sec - start.tv_sec;
    int nsec = end.tv_nsec - start.tv_nsec;
    if (nsec < 0) {
        sec--;
        nsec += 1000000000;
    }
    return sec * 1000000 + nsec / 1000;
}

void TimerProbe::print(const timespec& r, const timespec& p,
        const timespec& t) const
{
    uint32_t es = ElapsedTime(gRealBase, mRealStart);
    uint32_t er = ElapsedTime(mRealStart, r);
    uint32_t ep = ElapsedTime(mPStart, p);
    uint32_t et = ElapsedTime(mTStart, t);
    if (mIndent > 0) {
        Bucket& bucket = gBuckets.editItemAt(mBucket);
        if (bucket.mStart == 0)
            bucket.mStart = es;
        bucket.mReal += er;
        bucket.mProcess += ep;
        bucket.mThread += et;
        bucket.mCount++;
        return;
    }
    int index = 0;
    int buckets = gBuckets.size();
    int count = 1;
    const char* tag = mTag;
    int indent = mIndent;
    do {
        LOGD("%-30.30s: (%3d) %-5.*s time=%-10.3f real=%7dus process=%7dus (%3d%%) thread=%7dus (%3d%%)\n", 
            tag, count, indent > 5 ? 5 : indent, "+++++", es / 1000000.0,
            er, ep, ep * 100 / er, et, et * 100 / er);
        if (index >= buckets)
            break;
        Bucket& bucket = gBuckets.editItemAt(index);
        count = bucket.mCount;
        es = bucket.mStart;
        er = bucket.mReal;
        ep = bucket.mProcess;
        et = bucket.mThread;
        tag = bucket.mTag;
        indent = bucket.mIndent;
        *bucket.mSlotPtr = 0;
    } while (++index); // always true
    gBuckets.clear();
}

}; // namespace android

#endif