1 /*
2 * Licensed to the Apache Software Foundation (ASF) under one or more
3 * contributor license agreements. See the NOTICE file distributed with
4 * this work for additional information regarding copyright ownership.
5 * The ASF licenses this file to You under the Apache License, Version 2.0
6 * (the "License"); you may not use this file except in compliance with
7 * the License. You may obtain a copy of the License at
8 *
9 * http://www.apache.org/licenses/LICENSE-2.0
10 *
11 * Unless required by applicable law or agreed to in writing, software
12 * distributed under the License is distributed on an "AS IS" BASIS,
13 * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
14 * See the License for the specific language governing permissions and
15 * limitations under the License.
16 *
17 */
18
19 package org.apache.jmeter.reporters;
20
21 import java.io.Serializable;
22 import java.text.DecimalFormat;
23 import java.util.Hashtable;
24 import java.util.Map;
25
26 import org.apache.jmeter.engine.event.LoopIterationEvent;
27 import org.apache.jmeter.engine.util.NoThreadClone;
28 import org.apache.jmeter.samplers.Remoteable;
29 import org.apache.jmeter.samplers.SampleEvent;
30 import org.apache.jmeter.samplers.SampleListener;
31 import org.apache.jmeter.samplers.SampleResult;
32 import org.apache.jmeter.testelement.AbstractTestElement;
33 import org.apache.jmeter.testelement.TestListener;
34 import org.apache.jmeter.util.JMeterUtils;
35 import org.apache.jmeter.visualizers.RunningSample;
36 import org.apache.jorphan.logging.LoggingManager;
37 import org.apache.jorphan.util.JOrphanUtils;
38 import org.apache.log.Logger;
39
40 /**
41 * Generate a summary of the test run so far to the log file and/or standard
42 * output. Both running and differential totals are shown. Output is generated
43 * every n seconds (default 3 minutes) on the appropriate time boundary, so that
44 * multiple test runs on the same time will be synchronised.
45 *
46 * This is mainly intended for batch (non-GUI) runs
47 *
48 * Note that the RunningSample start and end times relate to the samples,
49 * not the reporting interval.
50 *
51 * Since the first sample in a delta is likely to have started in the previous reporting interval,
52 * this means that the delta interval is likely to be longer than the reporting interval.
53 *
54 * Also, the sum of the delta intervals will be larger than the overall elapsed time.
55 *
56 * Data is accumulated according to the test element name.
57 *
58 */
59 public class Summariser extends AbstractTestElement
60 implements Serializable, SampleListener, TestListener, NoThreadClone, Remoteable {
61
62 /*
63 * N.B. NoThreadClone is used to ensure that the testStarted() methods will share the same
64 * instance as the sampleOccured() methods, so the testStarted() method can fetch the
65 * Totals accumulator object for the samples to be stored in.
66 */
67
68 private static final long serialVersionUID = 233L;
69
70 private static final Logger log = LoggingManager.getLoggerForClass();
71
72 /** interval between summaries (in seconds) default 3 minutes */
73 private static final long INTERVAL = JMeterUtils.getPropDefault("summariser.interval", 3 * 60); //$NON-NLS-1$
74
75 /** Write messages to log file ? */
76 private static final boolean TOLOG = JMeterUtils.getPropDefault("summariser.log", true); //$NON-NLS-1$
77
78 /** Write messages to System.out ? */
79 private static final boolean TOOUT = JMeterUtils.getPropDefault("summariser.out", true); //$NON-NLS-1$
80
81 /*
82 * Ensure that a report is not skipped if we are slightly late in checking
83 * the time.
84 */
85 private static final int INTERVAL_WINDOW = 5; // in seconds
86
87 /*
88 * This map allows summarisers with the same name to contribute to the same totals.
89 */
90 //@GuardedBy("accumulators")
91 private static final Hashtable accumulators = new Hashtable();
92
93 //@GuardedBy("accumulators")
94 private static int instanceCount; // number of active tests
95
96 /*
97 * Cached copy of Totals for this instance.
98 * The variables do not need to be synchronised,
99 * as they are not shared between threads
100 * However the contents do need to be synchronized.
101 */
102 //@GuardedBy("myTotals")
103 private transient Totals myTotals = null;
104
105 // Name of the accumulator. Set up by testStarted().
106 private transient String myName;
107
108 /*
109 * Constructor is initially called once for each occurrence in the test plan.
110 * For GUI, several more instances are created.
111 * Then clear is called at start of test.
112 * Called several times during test startup.
113 * The name will not necessarily have been set at this point.
114 */
115 public Summariser() {
116 super();
117 synchronized (accumulators) {
118 accumulators.clear();
119 instanceCount=0;
120 }
121 }
122
123 /**
124 * Constructor for use during startup (intended for non-GUI use)
125 *
126 * @param name of summariser
127 */
128 public Summariser(String name) {
129 this();
130 setName(name);
131 }
132
133 /*
134 * Contains the items needed to collect stats for a summariser
135 *
136 */
137 private static class Totals {
138
139 /** Time of last summary (to prevent double reporting) */
140 private long last = 0;
141
142 private final RunningSample delta = new RunningSample("DELTA",0);
143
144 private final RunningSample total = new RunningSample("TOTAL",0);
145
146 /**
147 * Add the delta values to the total values and clear the delta
148 */
149 private void moveDelta() {
150 total.addSample(delta);
151 delta.clear();
152 }
153 }
154
155 /**
156 * Accumulates the sample in two SampleResult objects - one for running
157 * totals, and the other for deltas.
158 *
159 * @see org.apache.jmeter.samplers.SampleListener#sampleOccurred(org.apache.jmeter.samplers.SampleEvent)
160 */
161 public void sampleOccurred(SampleEvent e) {
162 SampleResult s = e.getResult();
163
164 long now = System.currentTimeMillis() / 1000;// in seconds
165
166 RunningSample myDelta = null;
167 RunningSample myTotal = null;
168 boolean reportNow = false;
169
170 /*
171 * Have we reached the reporting boundary?
172 * Need to allow for a margin of error, otherwise can miss the slot.
173 * Also need to check we've not hit the window already
174 */
175 synchronized (myTotals) {
176 if (s != null) {
177 myTotals.delta.addSample(s);
178 }
179
180 if ((now > myTotals.last + INTERVAL_WINDOW) && (now % INTERVAL <= INTERVAL_WINDOW)) {
181 reportNow = true;
182
183 // copy the data to minimise the synch time
184 myDelta = new RunningSample(myTotals.delta);
185 myTotals.moveDelta();
186 myTotal = new RunningSample(myTotals.total);
187
188 myTotals.last = now; // stop double-reporting
189 }
190 }
191 if (reportNow) {
192 String str;
193 str = format(myName, myDelta, "+");
194 if (TOLOG) {
195 log.info(str);
196 }
197 if (TOOUT) {
198 System.out.println(str);
199 }
200
201 // Only if we have updated them
202 if (myTotal != null && myDelta != null &&myTotal.getNumSamples() != myDelta.getNumSamples()) {
203 str = format(myName, myTotal, "=");
204 if (TOLOG) {
205 log.info(str);
206 }
207 if (TOOUT) {
208 System.out.println(str);
209 }
210 }
211 }
212 }
213
214 private static StringBuffer longToSb(StringBuffer sb, long l, int len) {
215 sb.setLength(0);
216 sb.append(l);
217 return JOrphanUtils.rightAlign(sb, len);
218 }
219
220 private static final DecimalFormat dfDouble = new DecimalFormat("#0.0"); // $NON-NLS-1$
221
222 private static StringBuffer doubleToSb(StringBuffer sb, double d, int len, int frac) {
223 sb.setLength(0);
224 dfDouble.setMinimumFractionDigits(frac);
225 dfDouble.setMaximumFractionDigits(frac);
226 sb.append(dfDouble.format(d));
227 return JOrphanUtils.rightAlign(sb, len);
228 }
229
230 /**
231 * @param myTotal
232 * @param string
233 * @return
234 */
235 private String format(String name, RunningSample s, String type) {
236 StringBuffer tmp = new StringBuffer(20); // for intermediate use
237 StringBuffer sb = new StringBuffer(100); // output line buffer
238 sb.append(name);
239 sb.append(" ");
240 sb.append(type);
241 sb.append(" ");
242 sb.append(longToSb(tmp, s.getNumSamples(), 5));
243 sb.append(" in ");
244 long elapsed = s.getElapsed();
245 sb.append(doubleToSb(tmp, elapsed / 1000.0, 5, 1));
246 sb.append("s = ");
247 if (elapsed > 0) {
248 sb.append(doubleToSb(tmp, s.getRate(), 6, 1));
249 } else {
250 sb.append("******");// Rate is effectively infinite
251 }
252 sb.append("/s Avg: ");
253 sb.append(longToSb(tmp, s.getAverage(), 5));
254 sb.append(" Min: ");
255 sb.append(longToSb(tmp, s.getMin(), 5));
256 sb.append(" Max: ");
257 sb.append(longToSb(tmp, s.getMax(), 5));
258 sb.append(" Err: ");
259 sb.append(longToSb(tmp, s.getErrorCount(), 5));
260 sb.append(" (");
261 sb.append(s.getErrorPercentageString());
262 sb.append(")");
263 return sb.toString();
264 }
265
266 /*
267 * (non-Javadoc)
268 *
269 * @see org.apache.jmeter.samplers.SampleListener#sampleStarted(org.apache.jmeter.samplers.SampleEvent)
270 */
271 public void sampleStarted(SampleEvent e) {
272 // not used
273 }
274
275 /*
276 * (non-Javadoc)
277 *
278 * @see org.apache.jmeter.samplers.SampleListener#sampleStopped(org.apache.jmeter.samplers.SampleEvent)
279 */
280 public void sampleStopped(SampleEvent e) {
281 // not used
282 }
283
284 /*
285 * The testStarted/testEnded methods are called at the start and end of a test.
286 *
287 * However, when a test is run on multiple nodes, there is no guarantee that all the
288 * testStarted() methods will be called before all the threadStart() or sampleOccurred()
289 * methods for other threads - nor that testEnded() will only be called after all
290 * sampleOccurred() calls. The ordering is only guaranteed within a single test.
291 *
292 */
293
294
295 /*
296 * (non-Javadoc)
297 *
298 * @see org.apache.jmeter.testelement.TestListener#testStarted()
299 */
300 public void testStarted() {
301 testStarted("local");
302 }
303
304 /*
305 * (non-Javadoc)
306 *
307 * @see org.apache.jmeter.testelement.TestListener#testEnded()
308 */
309 public void testEnded() {
310 testEnded("local");
311 }
312
313 /*
314 * (non-Javadoc)
315 *
316 * Called once for each Summariser in the test plan.
317 * There may be more than one summariser with the same name,
318 * however they will all be called before the test proper starts.
319 *
320 * However, note that this applies to a single test only.
321 * When running in client-server mode, testStarted() may be
322 * invoked after sampleOccurred().
323 *
324 * @see org.apache.jmeter.testelement.TestListener#testStarted(java.lang.String)
325 */
326 public void testStarted(String host) {
327 synchronized (accumulators) {
328 myName = getName();
329 myTotals = (Totals) accumulators.get(myName);
330 if (myTotals == null){
331 myTotals = new Totals();
332 accumulators.put(myName, myTotals);
333 }
334 instanceCount++;
335 }
336 }
337
338 /*
339 * (non-Javadoc)
340 * Called from a different thread as testStarted() but using the same instance.
341 * So synch is needed to fetch the accumulator, and the myName field will already be set up.
342 * @see org.apache.jmeter.testelement.TestListener#testEnded(java.lang.String)
343 */
344 public void testEnded(String host) {
345 Object[] totals = null;
346 synchronized (accumulators) {
347 instanceCount--;
348 if (instanceCount <= 0){
349 totals = accumulators.entrySet().toArray();
350 }
351 }
352 if (totals == null) {// We're not done yet
353 return;
354 }
355 for (int i=0; i<totals.length; i++) {
356 Map.Entry me = (Map.Entry)totals[i];
357 String str;
358 String name = (String) me.getKey();
359 Totals total = (Totals) me.getValue();
360 // Only print final delta if there were some samples in the delta
361 // and there has been at least one sample reported previously
362 if (total.delta.getNumSamples() > 0 && total.total.getNumSamples() > 0) {
363 str = format(name, total.delta, "+");
364 if (TOLOG) {
365 log.info(str);
366 }
367 if (TOOUT) {
368 System.out.println(str);
369 }
370 }
371 total.moveDelta();
372 str = format(name, total.total, "=");
373 if (TOLOG) {
374 log.info(str);
375 }
376 if (TOOUT) {
377 System.out.println(str);
378 }
379 }
380 }
381
382 /*
383 * (non-Javadoc)
384 *
385 * @see org.apache.jmeter.testelement.TestListener#testIterationStart(org.apache.jmeter.engine.event.LoopIterationEvent)
386 */
387 public void testIterationStart(LoopIterationEvent event) {
388 // not used
389 }
390 }