1 /* 2 * Copyright (C) 2018 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 package com.android.internal.util; 18 19 import android.os.SystemClock; 20 import android.util.Slog; 21 import android.util.proto.ProtoOutputStream; 22 23 import com.android.internal.annotations.GuardedBy; 24 import com.android.server.StatLoggerProto; 25 import com.android.server.StatLoggerProto.Event; 26 27 import java.io.PrintWriter; 28 29 /** 30 * Simple class to keep track of the number of times certain events happened and their durations for 31 * benchmarking. 32 * 33 * @hide 34 */ 35 public class StatLogger { 36 private static final String TAG = "StatLogger"; 37 38 private final Object mLock = new Object(); 39 40 private final int SIZE; 41 42 @GuardedBy("mLock") 43 private final int[] mCountStats; 44 45 @GuardedBy("mLock") 46 private final long[] mDurationStats; 47 48 @GuardedBy("mLock") 49 private final int[] mCallsPerSecond; 50 51 @GuardedBy("mLock") 52 private final long[] mDurationPerSecond; 53 54 @GuardedBy("mLock") 55 private final int[] mMaxCallsPerSecond; 56 57 @GuardedBy("mLock") 58 private final long[] mMaxDurationPerSecond; 59 60 @GuardedBy("mLock") 61 private final long[] mMaxDurationStats; 62 63 @GuardedBy("mLock") 64 private long mNextTickTime = SystemClock.elapsedRealtime() + 1000; 65 66 private final String[] mLabels; 67 StatLogger(String[] eventLabels)68 public StatLogger(String[] eventLabels) { 69 SIZE = eventLabels.length; 70 mCountStats = new int[SIZE]; 71 mDurationStats = new long[SIZE]; 72 mCallsPerSecond = new int[SIZE]; 73 mMaxCallsPerSecond = new int[SIZE]; 74 mDurationPerSecond = new long[SIZE]; 75 mMaxDurationPerSecond = new long[SIZE]; 76 mMaxDurationStats = new long[SIZE]; 77 mLabels = eventLabels; 78 } 79 80 /** 81 * Return the current time in the internal time unit. 82 * Call it before an event happens, and 83 * give it back to the {@link #logDurationStat(int, long)}} after the event. 84 */ getTime()85 public long getTime() { 86 return SystemClock.elapsedRealtimeNanos() / 1000; 87 } 88 89 /** 90 * @see {@link #getTime()} 91 * 92 * @return the duration in microseconds. 93 */ logDurationStat(int eventId, long start)94 public long logDurationStat(int eventId, long start) { 95 synchronized (mLock) { 96 final long duration = getTime() - start; 97 if (eventId >= 0 && eventId < SIZE) { 98 mCountStats[eventId]++; 99 mDurationStats[eventId] += duration; 100 } else { 101 Slog.wtf(TAG, "Invalid event ID: " + eventId); 102 return duration; 103 } 104 if (mMaxDurationStats[eventId] < duration) { 105 mMaxDurationStats[eventId] = duration; 106 } 107 108 // Keep track of the per-second max. 109 final long nowRealtime = SystemClock.elapsedRealtime(); 110 if (nowRealtime > mNextTickTime) { 111 if (mMaxCallsPerSecond[eventId] < mCallsPerSecond[eventId]) { 112 mMaxCallsPerSecond[eventId] = mCallsPerSecond[eventId]; 113 } 114 if (mMaxDurationPerSecond[eventId] < mDurationPerSecond[eventId]) { 115 mMaxDurationPerSecond[eventId] = mDurationPerSecond[eventId]; 116 } 117 118 mCallsPerSecond[eventId] = 0; 119 mDurationPerSecond[eventId] = 0; 120 121 mNextTickTime = nowRealtime + 1000; 122 } 123 124 mCallsPerSecond[eventId]++; 125 mDurationPerSecond[eventId] += duration; 126 127 return duration; 128 } 129 } 130 dump(PrintWriter pw, String prefix)131 public void dump(PrintWriter pw, String prefix) { 132 dump(new IndentingPrintWriter(pw, " ").setIndent(prefix)); 133 } 134 dump(IndentingPrintWriter pw)135 public void dump(IndentingPrintWriter pw) { 136 synchronized (mLock) { 137 pw.println("Stats:"); 138 pw.increaseIndent(); 139 for (int i = 0; i < SIZE; i++) { 140 final int count = mCountStats[i]; 141 final double durationMs = mDurationStats[i] / 1000.0; 142 143 pw.println(String.format( 144 "%s: count=%d, total=%.1fms, avg=%.3fms, max calls/s=%d max dur/s=%.1fms" 145 + " max time=%.1fms", 146 mLabels[i], count, durationMs, 147 (count == 0 ? 0 : durationMs / count), 148 mMaxCallsPerSecond[i], mMaxDurationPerSecond[i] / 1000.0, 149 mMaxDurationStats[i] / 1000.0)); 150 } 151 pw.decreaseIndent(); 152 } 153 } 154 dumpProto(ProtoOutputStream proto, long fieldId)155 public void dumpProto(ProtoOutputStream proto, long fieldId) { 156 synchronized (mLock) { 157 final long outer = proto.start(fieldId); 158 159 for (int i = 0; i < mLabels.length; i++) { 160 final long inner = proto.start(StatLoggerProto.EVENTS); 161 162 proto.write(Event.EVENT_ID, i); 163 proto.write(Event.LABEL, mLabels[i]); 164 proto.write(Event.COUNT, mCountStats[i]); 165 proto.write(Event.TOTAL_DURATION_MICROS, mDurationStats[i]); 166 167 proto.end(inner); 168 } 169 170 proto.end(outer); 171 } 172 } 173 } 174