1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25 package org.slf4j.profiler;
26
27 import java.util.ArrayList;
28 import java.util.List;
29
30 import org.slf4j.Logger;
31 import org.slf4j.Marker;
32 import org.slf4j.MarkerFactory;
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50 public class Profiler implements TimeInstrument {
51
52 final static String PROFILER_MARKER_NAME = "PROFILER";
53
54 final static int MIN_SW_NAME_LENGTH = 24;
55 final static int MIN_SW_ELAPSED_TIME_NUMBER_LENGTH = 9;
56
57 final String name;
58 final StopWatch globalStopWatch;
59
60 List<TimeInstrument> childTimeInstrumentList = new ArrayList<>();
61
62
63 ProfilerRegistry profilerRegistry;
64
65 Logger logger;
66
67 public Profiler(String name) {
68 this.name = name;
69 this.globalStopWatch = new StopWatch(name);
70 }
71
72 public String getName() {
73 return name;
74 }
75
76 public ProfilerRegistry getProfilerRegistry() {
77 return profilerRegistry;
78 }
79
80 public void registerWith(ProfilerRegistry profilerRegistry) {
81 if (profilerRegistry == null) {
82 return;
83 }
84 this.profilerRegistry = profilerRegistry;
85 profilerRegistry.put(this);
86 }
87
88 public Logger getLogger() {
89 return logger;
90 }
91
92 public void setLogger(Logger logger) {
93 this.logger = logger;
94 }
95
96
97
98
99
100 public void start(String name) {
101 stopLastTimeInstrument();
102 StopWatch childSW = new StopWatch(name);
103 childTimeInstrumentList.add(childSW);
104 }
105
106 public Profiler startNested(String name) {
107 stopLastTimeInstrument();
108 Profiler nestedProfiler = new Profiler(name);
109 nestedProfiler.registerWith(profilerRegistry);
110 nestedProfiler.setLogger(logger);
111 childTimeInstrumentList.add(nestedProfiler);
112 return nestedProfiler;
113 }
114
115 TimeInstrument getLastTimeInstrument() {
116 if (childTimeInstrumentList.size() > 0) {
117 return childTimeInstrumentList.get(childTimeInstrumentList.size() - 1);
118 } else {
119 return null;
120 }
121 }
122
123 void stopLastTimeInstrument() {
124 TimeInstrument last = getLastTimeInstrument();
125 if (last != null) {
126 last.stop();
127 }
128 }
129
130
131
132
133
134
135
136
137 public long elapsedTime() {
138 return globalStopWatch.elapsedTime();
139 }
140
141 public TimeInstrument stop() {
142 stopLastTimeInstrument();
143 globalStopWatch.stop();
144 return this;
145 }
146
147 public TimeInstrumentStatus getStatus() {
148 return globalStopWatch.status;
149 }
150
151
152
153
154 void sanityCheck() throws IllegalStateException {
155 if (getStatus() != TimeInstrumentStatus.STOPPED) {
156 throw new IllegalStateException("time instrument [" + getName() + " is not stopped");
157 }
158
159 long totalElapsed = globalStopWatch.elapsedTime();
160 long childTotal = 0;
161
162 for (TimeInstrument ti : childTimeInstrumentList) {
163 childTotal += ti.elapsedTime();
164 if (ti.getStatus() != TimeInstrumentStatus.STOPPED) {
165 throw new IllegalStateException("time instrument [" + ti.getName() + " is not stopped");
166 }
167 if (ti instanceof Profiler) {
168 Profiler nestedProfiler = (Profiler) ti;
169 nestedProfiler.sanityCheck();
170 }
171 }
172 if (totalElapsed < childTotal) {
173 throw new IllegalStateException("children have a higher accumulated elapsed time");
174 }
175 }
176
177 static String TOP_PROFILER_FIRST_PREFIX = "+";
178 static String NESTED_PROFILER_FIRST_PREFIX = "|---+";
179 static String TOTAL_ELAPSED = " Total ";
180 static String SUBTOTAL_ELAPSED = " Subtotal ";
181 static String ELAPSED_TIME = " elapsed time ";
182
183 public void print() {
184 System.out.println(toString());
185 }
186
187 @Override
188 public String toString() {
189 DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
190 return buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
191 }
192
193 public void log() {
194 Marker profilerMarker = MarkerFactory.getMarker(PROFILER_MARKER_NAME);
195 if (logger == null) {
196 throw new NullPointerException("If you invoke the log() method, then you must associate a logger with this profiler.");
197 }
198 if (logger.isDebugEnabled(profilerMarker)) {
199 DurationUnit du = Util.selectDurationUnitForDisplay(globalStopWatch);
200 String r = buildProfilerString(du, TOP_PROFILER_FIRST_PREFIX, TOTAL_ELAPSED, "");
201 logger.debug(profilerMarker, SpacePadder.LINE_SEP + r);
202 }
203 }
204
205
206
207
208
209
210
211 public List<TimeInstrument> getCopyOfChildTimeInstruments() {
212 List<TimeInstrument> copy = new ArrayList<>(childTimeInstrumentList);
213 return copy;
214 }
215
216
217
218
219
220
221
222 public StopWatch getCopyOfGlobalStopWatch() {
223 StopWatch copy = new StopWatch(globalStopWatch);
224 return copy;
225 }
226
227 private String buildProfilerString(DurationUnit du, String firstPrefix, String label, String indentation) {
228 StringBuilder buf = new StringBuilder();
229
230 buf.append(firstPrefix);
231 buf.append(" Profiler [");
232 buf.append(name);
233 buf.append("]");
234 buf.append(SpacePadder.LINE_SEP);
235 for (TimeInstrument child : childTimeInstrumentList) {
236 if (child instanceof StopWatch) {
237 buildStopWatchString(buf, du, ELAPSED_TIME, indentation, (StopWatch) child);
238 } else if (child instanceof Profiler) {
239 Profiler profiler = (Profiler) child;
240 String subString = profiler.buildProfilerString(du, NESTED_PROFILER_FIRST_PREFIX, SUBTOTAL_ELAPSED, indentation + " ");
241 buf.append(subString);
242 buildStopWatchString(buf, du, ELAPSED_TIME, indentation, profiler.globalStopWatch);
243 }
244 }
245 buildStopWatchString(buf, du, label, indentation, globalStopWatch);
246 return buf.toString();
247 }
248
249 private static void buildStopWatchString(StringBuilder buf, DurationUnit du, String prefix, String indentation, StopWatch sw) {
250
251 buf.append(indentation);
252 buf.append("|--");
253 buf.append(prefix);
254 SpacePadder.leftPad(buf, "[" + sw.getName() + "]", MIN_SW_NAME_LENGTH);
255 buf.append(" ");
256 String timeStr = Util.durationInDurationUnitsAsStr(sw.elapsedTime(), du);
257 SpacePadder.leftPad(buf, timeStr, MIN_SW_ELAPSED_TIME_NUMBER_LENGTH);
258 buf.append(" ");
259 Util.appendDurationUnitAsStr(buf, du);
260 buf.append(SpacePadder.LINE_SEP);
261 }
262 }