/*
* Copyright (C) 2013 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 com.android.mail.perf;
import android.os.Debug;
import android.os.SystemClock;
import com.android.mail.utils.LogTag;
import com.android.mail.utils.LogUtils;
import com.google.common.collect.Maps;
import java.util.ArrayList;
import java.util.Map;
import java.util.concurrent.ConcurrentHashMap;
/**
* Performance timing utilities for Gmail.
*
* There are two main ways to log performance. For simple, one off events, the static methods
* {@link #startTiming} and {@link #stopTiming} are sufficient:
*
*
* Timer.startTiming("myEvent");
* ... code for myEvent ...
* Timer.stopTiming("myEvent");
*
*
* The other way is to instantiate a timer that can be passed around, and started and paused. The
* timer will accumulate the results for each tag, and dump the results when asked.
*
*
* Timer timer = new Timer();
*
* for (int i = 0; i < lots; i++) {
* timer.start("tagA");
* ... code for tagA ...
* timer.pause("tagA");
* ... code that isn't relevant to timing ...
* }
*
* timer.dumpResults();
*
*
*/
public class Timer {
private static final String LOG_TAG = LogTag.getLogTag();
// set this to false to compile out all timer calls
public static final boolean ENABLE_TIMER = false;
// Set to true to enable logging of performance stats.
private static final boolean LOG_PERFORMANCE_STATS = true;
/** An internal structure used for performance markers. */
private static class PerformancePoint {
public final long mCpuTimeNanos;
public final long mWallTimeMillis;
public PerformancePoint() {
mCpuTimeNanos = Debug.threadCpuTimeNanos();
mWallTimeMillis = SystemClock.uptimeMillis();
}
}
private final Map> mPoints = Maps.newHashMap();
private final Map mCounts = Maps.newHashMap();
private final boolean mEnabled;
public Timer() {
this(false);
}
public Timer(boolean enable) {
mEnabled = enable;
}
@SuppressWarnings("unused")
public boolean isEnabled() {
return ENABLE_TIMER && mEnabled;
}
/**
* Starts timing an event indicated by the {@code tag}.
*/
@SuppressWarnings("unused")
public void start(String tag) {
if (ENABLE_TIMER && mEnabled) {
ArrayList values = mPoints.get(tag);
if (values == null) {
values = new ArrayList();
mPoints.put(tag, values);
}
if (values.size() % 2 == 0) {
values.add(new PerformancePoint());
}
}
}
/**
* Stops timing an event indicated by the {@code tag}
*/
@SuppressWarnings("unused")
public void pause(String tag) {
if (ENABLE_TIMER && mEnabled) {
ArrayList values = mPoints.get(tag);
if (values != null && values.size() % 2 == 1) {
values.add(new PerformancePoint());
}
}
}
@SuppressWarnings("unused")
public void count(String tag) {
if (ENABLE_TIMER && mEnabled) {
Integer counts = mCounts.get(tag);
if (counts == null) {
counts = 0;
}
mCounts.put(tag, counts + 1);
}
}
@SuppressWarnings("unused")
public void clear() {
if (ENABLE_TIMER && mEnabled) {
mPoints.clear();
mCounts.clear();
}
}
/**
* Dumps cumulative timing results for all tags recognized by this timer.
*/
@SuppressWarnings("unused")
public void dumpResults() {
if (ENABLE_TIMER && mEnabled) {
for (Map.Entry> entry : mPoints.entrySet()) {
String tag = entry.getKey();
ArrayList values = entry.getValue();
long cpuDurationNanos = 0;
long wallDurationMillis = 0;
for (int i = 0; i < values.size() - 1; i += 2) {
PerformancePoint startPoint = values.get(i);
PerformancePoint endPoint = values.get(i + 1);
cpuDurationNanos += endPoint.mCpuTimeNanos - startPoint.mCpuTimeNanos;
wallDurationMillis += endPoint.mWallTimeMillis - startPoint.mWallTimeMillis;
}
if (cpuDurationNanos == 0) {
cpuDurationNanos = 1;
}
dumpTimings(tag, 1, cpuDurationNanos, wallDurationMillis);
}
if (LOG_PERFORMANCE_STATS) {
for (Map.Entry entry : mCounts.entrySet()) {
LogUtils.d(LOG_TAG, "Perf %s count: %d", entry.getKey(), entry.getValue());
}
}
}
}
/**
* Used for timing one off events.
*/
private static Map sPerformanceCollector =
new ConcurrentHashMap();
/**
* Starts a one-off timer for an event. The event is denoted by {@code tag} and only one event
* of that tag may be timed at a given time.
*/
public static void startTiming(String tag) {
if (ENABLE_TIMER) {
sPerformanceCollector.put(tag, new PerformancePoint());
}
}
/**
* Stops a one-off timer for an event indicated by {@code tag}.
*/
public static void stopTiming(String tag) {
if (ENABLE_TIMER) {
stopTiming(tag, 1 /* one subiteration */);
}
}
/**
* Stops a one-off timer for an event indicated by {@code tag}, and indicates that the event
* consisted of {@code numSubIterations} sub-events, so that performance output will be denoted
* as such.
*/
public static void stopTiming(String tag, int numSubIterations) {
if (ENABLE_TIMER) {
PerformancePoint endPoint = new PerformancePoint();
PerformancePoint startPoint = sPerformanceCollector.get(tag);
if (startPoint == null) {
return;
}
long cpuDurationNanos = endPoint.mCpuTimeNanos - startPoint.mCpuTimeNanos;
long wallDurationMillis = endPoint.mWallTimeMillis - startPoint.mWallTimeMillis;
// Make sure cpu Duration is non 0
if (cpuDurationNanos == 0) {
cpuDurationNanos = 1;
}
dumpTimings(tag, numSubIterations, cpuDurationNanos, wallDurationMillis);
}
}
private static void dumpTimings(String tag, int numSubIterations,
long cpuDurationNanos, long wallDurationMillis) {
if (LOG_PERFORMANCE_STATS) {
LogUtils.d(LOG_TAG, "Perf %s wall: %d cpu: %d",
tag, wallDurationMillis, (cpuDurationNanos / 1000000));
// print out the average time for each sub iteration
if (numSubIterations > 1) {
LogUtils.d(LOG_TAG, "Perf/operation %s wall: %d cpu: %d", tag,
(wallDurationMillis / numSubIterations),
((cpuDurationNanos / 1000000) / numSubIterations));
}
}
}
}