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