| // Copyright 2010 Google Inc. All Rights Reserved. |
| |
| package com.android.email.perf; |
| |
| import com.google.common.collect.Maps; |
| import com.android.email.utils.LogUtils; |
| import com.android.email.utils.Utils; |
| |
| import android.os.Debug; |
| import android.os.SystemClock; |
| |
| 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: |
| * |
| * <pre> |
| * Timer.startTiming("myEvent"); |
| * ... code for myEvent ... |
| * Timer.stopTiming("myEvent"); |
| * </pre> |
| * |
| * 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. |
| * |
| * <pre> |
| * 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(); |
| * </pre> |
| * |
| */ |
| public class Timer { |
| private static final String LOG_TAG = new LogUtils().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<String, ArrayList<PerformancePoint>> mPoints = Maps.newHashMap(); |
| private final Map<String, Integer> 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<PerformancePoint> values = mPoints.get(tag); |
| if (values == null) { |
| values = new ArrayList<PerformancePoint>(); |
| 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<PerformancePoint> 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<String, ArrayList<PerformancePoint>> entry : mPoints.entrySet()) { |
| String tag = entry.getKey(); |
| ArrayList<PerformancePoint> 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<String, Integer> entry : mCounts.entrySet()) { |
| LogUtils.d(LOG_TAG, "Perf %s count: %d", entry.getKey(), entry.getValue()); |
| } |
| } |
| } |
| } |
| |
| /** |
| * Used for timing one off events. |
| */ |
| private static Map<String, PerformancePoint> sPerformanceCollector = |
| new ConcurrentHashMap<String, PerformancePoint>(); |
| |
| /** |
| * 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) { |
| // TODO(phamm): EventLogTags doens't work when building with SDK. |
| // EventLog.writeEvent(EventLogTags.GMAIL_PERF_END, tag, |
| // cpuDurationNanos / 1000000, wallDurationMillis, numSubIterations); |
| |
| 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)); |
| } |
| } |
| } |
| |
| } |