View Javadoc

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