001: /**
002: * Copyright 2003-2007 Luck Consulting Pty Ltd
003: *
004: * Licensed under the Apache License, Version 2.0 (the "License");
005: * you may not use this file except in compliance with the License.
006: * You may obtain a copy of the License at
007: *
008: * http://www.apache.org/licenses/LICENSE-2.0
009: *
010: * Unless required by applicable law or agreed to in writing, software
011: * distributed under the License is distributed on an "AS IS" BASIS,
012: * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
013: * See the License for the specific language governing permissions and
014: * limitations under the License.
015: */package net.sf.ehcache;
016:
017: import org.apache.commons.logging.Log;
018: import org.apache.commons.logging.LogFactory;
019: import net.sf.ehcache.util.PropertyUtil;
020:
021: /**
022: * A timer service used to check performance of tests.
023: * <p/>
024: * To enable this to work for different machines the following is done:
025: * <ul>
026: * <li>SimpleLog is used for logging with a known logging level controlled by <code>simplelog.properties</code>
027: * which is copied to the test classpath. This removes logging as a source of differences.
028: * Messages are sent to stderr which also makes it easy to see messages on remote continuous integration
029: * machines.
030: * <li>A speedAdjustmentFactor is used to equalize machines. It is supplied as a the System Property
031: * 'net.sf.ehcache.speedAdjustmentFactor=n', where n is the number of times the machine is slower
032: * than the reference machine e.g. 1.1. This factor is then used to adjust "elapsedTime"
033: * as returned by this class. Elapsed Time is therefore not true time, but notional time equalized with the reference
034: * machine. If you get performance tests failing add this property.
035: * </ul>
036: *
037: * @author Greg Luck
038: * @version $Id: StopWatch.java 519 2007-07-27 07:11:45Z gregluck $
039: * A stop watch that can be useful for instrumenting for performance
040: */
041: public class StopWatch {
042:
043: private static final Log LOG = LogFactory.getLog(StopWatch.class
044: .getName());
045:
046: private static final String SUFFIX = "ms";
047:
048: /**
049: * An attempt to adjust performance tests to different machines.
050: */
051: private static float speedAdjustmentFactor = 1;
052:
053: /**
054: * Used for performance benchmarking
055: */
056: private long timeStamp = System.currentTimeMillis();
057:
058: /**
059: * Get the speed adjustment factor
060: */
061: public static float getSpeedAdjustmentFactor() {
062: return speedAdjustmentFactor;
063: }
064:
065: static {
066:
067: String speedAdjustmentFactorString = PropertyUtil
068: .extractAndLogProperty(
069: "net.sf.ehcache.speedAdjustmentFactor", System
070: .getProperties());
071:
072: if (speedAdjustmentFactorString != null) {
073: try {
074: speedAdjustmentFactor = Float
075: .parseFloat(speedAdjustmentFactorString);
076: } catch (NumberFormatException e) {
077: LOG
078: .debug("Consider setting system property 'net.sf.ehcache.speedAdjustmentFactor=n' "
079: + "where n is the number of times your machine is slower than the reference machine, "
080: + "which is currently a dual G5 PowerMac. e.g. 1.2, which then enables elasped time "
081: + "measurement to be adjusted accordingly.");
082: }
083: LOG.debug("Using speedAjustmentFactor of "
084: + speedAdjustmentFactor);
085:
086: } else {
087: LOG
088: .debug("Consider setting system property 'net.sf.ehcache.speedAdjustmentFactor=n' "
089: + "where n is the number of times your machine is slower than the reference machine, "
090: + "which is currently a dual G5 PowerMac. e.g. 1.2, which then enables elasped time "
091: + "measurement to be adjusted accordingly.");
092: }
093:
094: StopWatch stopWatch = new StopWatch();
095: try {
096: Thread.sleep(100);
097: } catch (InterruptedException e) {
098: //
099: }
100: LOG.debug("100 measures as " + stopWatch.getElapsedTime());
101:
102: }
103:
104: // static {
105: //
106: // float referenceTime = 2050;
107: // CacheManager singletonManager = CacheManager.create(AbstractCacheTest.TEST_CONFIG_DIR + "ehcache-big.xml");
108: //
109: // String[] names = singletonManager.getCacheNames();
110: // for (int i = 0; i < names.length; i++) {
111: // String name = names[i];
112: // Ehcache cache = singletonManager.getCache(name);
113: // for (int j = 0; i < 100; i++) {
114: // cache.put(new Element(new Integer(j), "value"));
115: // }
116: // }
117: // long start = System.currentTimeMillis();
118: // for (int repeats = 0; repeats < 5000; repeats++) {
119: // for (int i = 0; i < names.length; i++) {
120: // String name = names[i];
121: // Ehcache cache = singletonManager.getCache(name);
122: // for (int j = 0; i < 100; i++) {
123: // Element element = cache.get(name + j);
124: // if ((element == null)) {
125: // cache.put(new Element(new Integer(j), "value"));
126: // }
127: // }
128: // }
129: // }
130: // long elapsedTime = System.currentTimeMillis() - start;
131: //
132: // LOG.error("It took this machine: " + elapsedTime + " to perform a time trial compared with the reference time of "
133: // + referenceTime + "ms");
134: //
135: // speedAdjustmentFactor = elapsedTime / referenceTime;
136: //
137: // LOG.error("Elapsed stopwatch times will be adjusted divided by " + speedAdjustmentFactor);
138: // }
139:
140: /**
141: * Gets the time elapsed between now and for the first time, the creation
142: * time of the class, and after that, between each call to this method
143: * <p/>
144: * Note this method returns notional time elapsed. See class description
145: */
146: public long getElapsedTime() {
147: long now = System.currentTimeMillis();
148: long elapsed = (long) ((now - timeStamp) / speedAdjustmentFactor);
149: timeStamp = now;
150: return elapsed;
151: }
152:
153: /**
154: * @return formatted elapsed Time
155: */
156: public String getElapsedTimeString() {
157: return String.valueOf(getElapsedTime()) + SUFFIX;
158: }
159:
160: }
|