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