android/util/TimingsTraceLog.java

/*
 * Copyright (C) 2016 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.
 */

package android.util;

import android.annotation.NonNull;
import android.os.Build;
import android.os.SystemClock;
import android.os.Trace;

import com.android.internal.annotations.VisibleForTesting;

import java.util.ArrayList;
import java.util.Collections;
import java.util.List;

/**
 * Helper class for reporting boot and shutdown timing metrics.
 *
 * <p><b>NOTE:</b> This class is not thread-safe. Use a separate copy for other threads.
 *
 * @hide
 */
public class TimingsTraceLog {
    // Debug boot time for every step if it's non-user build.
    private static final boolean DEBUG_BOOT_TIME = !Build.IS_USER;

    // Maximum number of nested calls that are stored
    private static final int MAX_NESTED_CALLS = 10;

    private final String[] mStartNames;
    private final long[] mStartTimes;

    private final String mTag;
    private final long mTraceTag;
    private final long mThreadId;
    private final int mMaxNestedCalls;

    private int mCurrentLevel = -1;

    public TimingsTraceLog(String tag, long traceTag) {
        this(tag, traceTag, DEBUG_BOOT_TIME ? MAX_NESTED_CALLS : -1);
    }

    @VisibleForTesting
    public TimingsTraceLog(String tag, long traceTag, int maxNestedCalls) {
        mTag = tag;
        mTraceTag = traceTag;
        mThreadId = Thread.currentThread().getId();
        mMaxNestedCalls = maxNestedCalls;
        this.mStartNames = createAndGetStartNamesArray();
        this.mStartTimes = createAndGetStartTimesArray();
    }

    /**
     * Note: all fields will be copied except for {@code mStartNames} and {@code mStartTimes}
     * in order to save memory. The copied object is only expected to be used at levels deeper than
     * the value of {@code mCurrentLevel} when the object is copied.
     *
     * @param other object to be copied
     */
    protected TimingsTraceLog(TimingsTraceLog other) {
        this.mTag = other.mTag;
        this.mTraceTag = other.mTraceTag;
        this.mThreadId = Thread.currentThread().getId();
        this.mMaxNestedCalls = other.mMaxNestedCalls;
        this.mStartNames = createAndGetStartNamesArray();
        this.mStartTimes = createAndGetStartTimesArray();
        this.mCurrentLevel = other.mCurrentLevel;
    }

    private String[] createAndGetStartNamesArray() {
        return mMaxNestedCalls > 0 ? new String[mMaxNestedCalls] : null;
    }

    private long[] createAndGetStartTimesArray() {
        return mMaxNestedCalls > 0 ? new long[mMaxNestedCalls] : null;
    }

    /**
     * Begin tracing named section
     * @param name name to appear in trace
     */
    public void traceBegin(String name) {
        assertSameThread();
        Trace.traceBegin(mTraceTag, name);

        if (!DEBUG_BOOT_TIME) return;

        if (mCurrentLevel + 1 >= mMaxNestedCalls) {
            Slog.w(mTag, "not tracing duration of '" + name + "' because already reached "
                    + mMaxNestedCalls + " levels");
            return;
        }

        mCurrentLevel++;
        mStartNames[mCurrentLevel] = name;
        mStartTimes[mCurrentLevel] = SystemClock.elapsedRealtime();
    }

    /**
     * End tracing previously {@link #traceBegin(String) started} section.
     *
     * <p>Also {@link #logDuration logs} the duration.
     */
    public void traceEnd() {
        assertSameThread();
        Trace.traceEnd(mTraceTag);

        if (!DEBUG_BOOT_TIME) return;

        if (mCurrentLevel < 0) {
            Slog.w(mTag, "traceEnd called more times than traceBegin");
            return;
        }

        final String name = mStartNames[mCurrentLevel];
        final long duration = SystemClock.elapsedRealtime() - mStartTimes[mCurrentLevel];
        mCurrentLevel--;

        logDuration(name, duration);
    }

    private void assertSameThread() {
        final Thread currentThread = Thread.currentThread();
        if (currentThread.getId() != mThreadId) {
            throw new IllegalStateException("Instance of TimingsTraceLog can only be called from "
                    + "the thread it was created on (tid: " + mThreadId + "), but was from "
                    + currentThread.getName() + " (tid: " + currentThread.getId() + ")");
        }
    }

    /**
     * Logs a duration so it can be parsed by external tools for performance reporting.
     */
    public void logDuration(String name, long timeMs) {
        Slog.v(mTag, name + " took to complete: " + timeMs + "ms");
    }

    /**
     * Gets the names of the traces that {@link #traceBegin(String) have begun} but
     * {@link #traceEnd() have not finished} yet.
     *
     * <p><b>NOTE:</b> this method is expensive and it should not be used in "production" - it
     * should only be used for debugging purposes during development (and/or guarded by
     * static {@code DEBUG} constants that are {@code false}).
     */
    @NonNull
    public final List<String> getUnfinishedTracesForDebug() {
        if (mStartTimes == null || mCurrentLevel < 0) return Collections.emptyList();
        final ArrayList<String> list = new ArrayList<>(mCurrentLevel + 1);
        for (int i = 0; i <= mCurrentLevel; i++) {
            list.add(mStartNames[i]);
        }
        return list;
    }
}