1 /**
2 * Copyright 2003-2007 Greg Luck
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 net.sf.ehcache;
18
19 import org.apache.commons.logging.Log;
20 import org.apache.commons.logging.LogFactory;
21 import net.sf.ehcache.util.PropertyUtil;
22
23 /**
24 * A timer service used to check performance of tests.
25 * <p/>
26 * To enable this to work for different machines the following is done:
27 * <ul>
28 * <li>SimpleLog is used for logging with a known logging level controlled by <code>simplelog.properties</code>
29 * which is copied to the test classpath. This removes logging as a source of differences.
30 * Messages are sent to stderr which also makes it easy to see messages on remote continuous integration
31 * machines.
32 * <li>A speedAdjustmentFactor is used to equalize machines. It is supplied as a the System Property
33 * 'net.sf.ehcache.speedAdjustmentFactor=n', where n is the number of times the machine is slower
34 * than the reference machine e.g. 1.1. This factor is then used to adjust "elapsedTime"
35 * as returned by this class. Elapsed Time is therefore not true time, but notional time equalized with the reference
36 * machine. If you get performance tests failing add this property.
37 * </ul>
38 *
39 * @author Greg Luck
40 * @version $Id: StopWatch.java 512 2007-07-10 09:18:45Z gregluck $
41 * A stop watch that can be useful for instrumenting for performance
42 */
43 public class StopWatch {
44
45 private static final Log LOG = LogFactory.getLog(StopWatch.class.getName());
46
47
48 private static final String SUFFIX = "ms";
49
50
51 /**
52 * An attempt to adjust performance tests to different machines.
53 */
54 private static float speedAdjustmentFactor = 1;
55
56
57 /**
58 * Used for performance benchmarking
59 */
60 private long timeStamp = System.currentTimeMillis();
61
62
63 /**
64 * Get the speed adjustment factor
65 */
66 public static float getSpeedAdjustmentFactor() {
67 return speedAdjustmentFactor;
68 }
69
70
71 static {
72
73 String speedAdjustmentFactorString =
74 PropertyUtil.extractAndLogProperty("net.sf.ehcache.speedAdjustmentFactor", System.getProperties());
75
76 if (speedAdjustmentFactorString != null) {
77 try {
78 speedAdjustmentFactor = Float.parseFloat(speedAdjustmentFactorString);
79 } catch (NumberFormatException e) {
80 LOG.debug("Consider setting system property 'net.sf.ehcache.speedAdjustmentFactor=n' " +
81 "where n is the number of times your machine is slower than the reference machine, " +
82 "which is currently a dual G5 PowerMac. e.g. 1.2, which then enables elasped time " +
83 "measurement to be adjusted accordingly.");
84 }
85 LOG.debug("Using speedAjustmentFactor of " + speedAdjustmentFactor);
86
87 } else {
88 LOG.debug("Consider setting system property 'net.sf.ehcache.speedAdjustmentFactor=n' " +
89 "where n is the number of times your machine is slower than the reference machine, " +
90 "which is currently a dual G5 PowerMac. e.g. 1.2, which then enables elasped time " +
91 "measurement to be adjusted accordingly.");
92 }
93
94 StopWatch stopWatch = new StopWatch();
95 try {
96 Thread.sleep(100);
97 } catch (InterruptedException e) {
98 //
99 }
100 LOG.debug("100 measures as " + stopWatch.getElapsedTime());
101
102
103 }
104
105 // static {
106 //
107 // float referenceTime = 2050;
108 // CacheManager singletonManager = CacheManager.create(AbstractCacheTest.TEST_CONFIG_DIR + "ehcache-big.xml");
109 //
110 // String[] names = singletonManager.getCacheNames();
111 // for (int i = 0; i < names.length; i++) {
112 // String name = names[i];
113 // Ehcache cache = singletonManager.getCache(name);
114 // for (int j = 0; i < 100; i++) {
115 // cache.put(new Element(new Integer(j), "value"));
116 // }
117 // }
118 // long start = System.currentTimeMillis();
119 // for (int repeats = 0; repeats < 5000; repeats++) {
120 // for (int i = 0; i < names.length; i++) {
121 // String name = names[i];
122 // Ehcache cache = singletonManager.getCache(name);
123 // for (int j = 0; i < 100; i++) {
124 // Element element = cache.get(name + j);
125 // if ((element == null)) {
126 // cache.put(new Element(new Integer(j), "value"));
127 // }
128 // }
129 // }
130 // }
131 // long elapsedTime = System.currentTimeMillis() - start;
132 //
133 // LOG.error("It took this machine: " + elapsedTime + " to perform a time trial compared with the reference time of "
134 // + referenceTime + "ms");
135 //
136 // speedAdjustmentFactor = elapsedTime / referenceTime;
137 //
138 // LOG.error("Elapsed stopwatch times will be adjusted divided by " + speedAdjustmentFactor);
139 // }
140
141
142 /**
143 * Gets the time elapsed between now and for the first time, the creation
144 * time of the class, and after that, between each call to this method
145 * <p/>
146 * Note this method returns notional time elapsed. See class description
147 */
148 public long getElapsedTime() {
149 long now = System.currentTimeMillis();
150 long elapsed = (long) ((now - timeStamp) / speedAdjustmentFactor);
151 timeStamp = now;
152 return elapsed;
153 }
154
155 /**
156 * @return formatted elapsed Time
157 */
158 public String getElapsedTimeString() {
159 return String.valueOf(getElapsedTime()) + SUFFIX;
160 }
161
162 }
163
164