Jonathan Hart | 23701d1 | 2014-04-03 10:45:48 -0700 | [diff] [blame] | 1 | package net.onrc.onos.core.util; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 2 | |
Brian O'Connor | 2daf7a9 | 2014-01-14 11:26:35 -0800 | [diff] [blame] | 3 | import java.util.Map.Entry; |
Brian O'Connor | a5e5f83 | 2014-01-15 16:58:14 -0800 | [diff] [blame] | 4 | import java.util.Queue; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 5 | import java.util.concurrent.ConcurrentHashMap; |
Brian O'Connor | a5e5f83 | 2014-01-15 16:58:14 -0800 | [diff] [blame] | 6 | import java.util.concurrent.ConcurrentLinkedQueue; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 7 | |
| 8 | import org.slf4j.Logger; |
| 9 | import org.slf4j.LoggerFactory; |
| 10 | |
| 11 | /** |
| 12 | * Class for collecting performance measurements |
| 13 | */ |
| 14 | public class PerformanceMonitor { |
Ray Milkey | ec83894 | 2014-04-09 11:28:43 -0700 | [diff] [blame] | 15 | private static final Logger log = LoggerFactory.getLogger(PerformanceMonitor.class); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 16 | |
| 17 | // experiment name -> PerformanceMonitor |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 18 | private static final ConcurrentHashMap<String, PerformanceMonitor> PERF_MONS = new ConcurrentHashMap<>(); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 19 | |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 20 | public static PerformanceMonitor experiment(String name) { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 21 | PerformanceMonitor pm = PERF_MONS.get(name); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 22 | if (pm == null) { |
| 23 | pm = new PerformanceMonitor(); |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 24 | PerformanceMonitor existing = PERF_MONS.putIfAbsent(name, pm); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 25 | if (existing != null) { |
| 26 | pm = existing; |
| 27 | } |
| 28 | } |
| 29 | return pm; |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 30 | } |
| 31 | |
| 32 | // tag -> Measurements |
| 33 | private final ConcurrentHashMap<String, Queue<Measurement>> map = new ConcurrentHashMap<>(); |
| 34 | private long overhead; |
| 35 | private long experimentStart = Long.MAX_VALUE; |
Ray Milkey | ec83894 | 2014-04-09 11:28:43 -0700 | [diff] [blame] | 36 | private static final double NORMALIZATION = Math.pow(10, 6); |
Brian O'Connor | 2daf7a9 | 2014-01-14 11:26:35 -0800 | [diff] [blame] | 37 | |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 38 | /** |
| 39 | * Start a performance measurement, identified by a tag |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 40 | * <p/> |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 41 | * Note: Only a single measurement can use the same tag at a time. |
Brian O'Connor | 2daf7a9 | 2014-01-14 11:26:35 -0800 | [diff] [blame] | 42 | * ..... not true anymore. |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 43 | * |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 44 | * @param tag for performance measurement |
| 45 | */ |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 46 | public Measurement startStep(String tag) { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 47 | long start = System.nanoTime(); |
| 48 | if (start < experimentStart) { |
| 49 | experimentStart = start; |
| 50 | } |
| 51 | Queue<Measurement> list = map.get(tag); |
| 52 | if (list == null) { |
| 53 | list = new ConcurrentLinkedQueue<Measurement>(); |
Ray Milkey | 2476cac | 2014-04-08 11:03:21 -0700 | [diff] [blame] | 54 | Queue<Measurement> existingList = map.putIfAbsent(tag, list); |
| 55 | if (existingList != null) { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 56 | // someone concurrently added, using theirs |
Ray Milkey | 2476cac | 2014-04-08 11:03:21 -0700 | [diff] [blame] | 57 | list = existingList; |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 58 | } |
| 59 | } |
| 60 | Measurement m = new Measurement(); |
| 61 | list.add(m); |
| 62 | m.start(); |
| 63 | overhead += System.nanoTime() - start; |
| 64 | return m; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 65 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 66 | |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 67 | /** |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 68 | * Stop a performance measurement. |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 69 | * <p/> |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 70 | * You must have already started a measurement with tag. |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 71 | * |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 72 | * @param tag for performance measurement |
| 73 | */ |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 74 | public void stopStep(String tag) { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 75 | long time = System.nanoTime(); |
| 76 | Queue<Measurement> list = map.get(tag); |
| 77 | if (list == null || list.size() == 0) { |
| 78 | log.error("Tag {} does not exist", tag); |
| 79 | } |
| 80 | list.peek().stop(time); |
| 81 | if (list.size() > 1) { |
| 82 | log.error("Tag {} has multiple measurements", tag); |
| 83 | } |
| 84 | overhead += System.nanoTime() - time; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 85 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 86 | |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 87 | /** |
| 88 | * Clear all performance measurements. |
| 89 | */ |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 90 | public void reset() { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 91 | map.clear(); |
| 92 | overhead = 0; |
| 93 | experimentStart = Long.MAX_VALUE; |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 94 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 95 | |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 96 | /** |
| 97 | * Write all performance measurements to the log |
| 98 | */ |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 99 | public void reportAll() { |
Pavlin Radoslavov | 424150c | 2014-04-09 12:12:36 -0700 | [diff] [blame] | 100 | StringBuilder result = new StringBuilder(); |
| 101 | |
| 102 | result.append("Performance Results: (avg/start/stop/count)\n"); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 103 | if (map.size() == 0) { |
Pavlin Radoslavov | 424150c | 2014-04-09 12:12:36 -0700 | [diff] [blame] | 104 | result.append("No Measurements"); |
| 105 | log.error(result.toString()); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 106 | return; |
| 107 | } |
| 108 | long experimentEnd = -1; |
| 109 | for (Entry<String, Queue<Measurement>> e : map.entrySet()) { |
| 110 | String key = e.getKey(); |
| 111 | Queue<Measurement> list = e.getValue(); |
| 112 | long total = 0, count = 0; |
| 113 | long start = Long.MAX_VALUE, stop = -1; |
| 114 | for (Measurement m : list) { |
| 115 | if (m.stop < 0) { |
| 116 | continue; // measurement has not been stopped |
| 117 | } |
| 118 | // Collect overall start and end times |
| 119 | if (m.start < start) { |
| 120 | start = m.start; |
| 121 | } |
| 122 | if (m.stop > stop) { |
| 123 | stop = m.stop; |
| 124 | if (stop > experimentEnd) { |
| 125 | experimentEnd = stop; |
| 126 | } |
| 127 | } |
| 128 | // Collect statistics for average |
| 129 | total += m.elapsed(); |
| 130 | count++; |
| 131 | } |
| 132 | double avg = (double) total / count; |
| 133 | // Normalize start/stop |
| 134 | start -= experimentStart; |
| 135 | stop -= experimentStart; |
Pavlin Radoslavov | 424150c | 2014-04-09 12:12:36 -0700 | [diff] [blame] | 136 | result.append(key + '=' + |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 137 | (avg / NORMALIZATION) + '/' + |
| 138 | (start / NORMALIZATION) + '/' + |
| 139 | (stop / NORMALIZATION) + '/' + |
Pavlin Radoslavov | 424150c | 2014-04-09 12:12:36 -0700 | [diff] [blame] | 140 | count + '\n'); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 141 | } |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 142 | double overheadMs = overhead / NORMALIZATION; |
| 143 | double experimentElapsed = (experimentEnd - experimentStart) / NORMALIZATION; |
Pavlin Radoslavov | 424150c | 2014-04-09 12:12:36 -0700 | [diff] [blame] | 144 | result.append("TotalTime:" + experimentElapsed + "/Overhead:" + overheadMs); |
| 145 | log.error(result.toString()); |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 146 | // log.error("Performance Results: {} with measurement overhead: {} ms", map, overheadMilli); |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 147 | } |
Pavlin Radoslavov | b5e3178 | 2014-01-12 20:11:46 -0800 | [diff] [blame] | 148 | |
| 149 | /** |
| 150 | * Write the performance measurement for a tag to the log |
| 151 | * |
| 152 | * @param tag the tag name. |
| 153 | */ |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 154 | public void reportStep(String tag) { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 155 | Queue<Measurement> list = map.get(tag); |
| 156 | if (list == null) { |
| 157 | return; //TODO |
| 158 | } |
| 159 | //TODO: fix this; |
| 160 | Measurement m = list.peek(); |
| 161 | if (m != null) { |
| 162 | log.error("Performance Result: tag = {} start = {} stop = {} elapsed = {}", |
| 163 | tag, m.start, m.stop, m.toString()); |
| 164 | } else { |
| 165 | log.error("Performance Result: unknown tag {}", tag); |
| 166 | } |
Pavlin Radoslavov | b5e3178 | 2014-01-12 20:11:46 -0800 | [diff] [blame] | 167 | } |
| 168 | |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 169 | /** |
| 170 | * A single performance measurement |
| 171 | */ |
Brian O'Connor | 2daf7a9 | 2014-01-14 11:26:35 -0800 | [diff] [blame] | 172 | public static class Measurement { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 173 | long start; |
| 174 | long stop = -1; |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 175 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 176 | /** |
| 177 | * Start the measurement |
| 178 | */ |
| 179 | public void start() { |
| 180 | if (start <= 0) { |
| 181 | start = System.nanoTime(); |
| 182 | } |
| 183 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 184 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 185 | /** |
| 186 | * Stop the measurement |
| 187 | */ |
| 188 | public void stop() { |
| 189 | long now = System.nanoTime(); |
| 190 | stop(now); |
| 191 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 192 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 193 | /** |
| 194 | * Stop the measurement at a specific time |
| 195 | * |
| 196 | * @param time to stop |
| 197 | */ |
| 198 | public void stop(long time) { |
| 199 | if (stop <= 0) { |
| 200 | stop = time; |
| 201 | } |
| 202 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 203 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 204 | /** |
| 205 | * Compute the elapsed time of the measurement in nanoseconds |
| 206 | * |
| 207 | * @return the measurement time in nanoseconds, or -1 if the measurement is stil running. |
| 208 | */ |
| 209 | public long elapsed() { |
| 210 | if (stop <= 0) { |
| 211 | return -1; |
| 212 | } else { |
| 213 | return stop - start; |
| 214 | } |
| 215 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 216 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 217 | /** |
| 218 | * Returns the number of milliseconds for the measurement as a String. |
| 219 | */ |
| 220 | @Override |
| 221 | public String toString() { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 222 | double milli = elapsed() / NORMALIZATION; |
| 223 | double startMs = start / NORMALIZATION; |
| 224 | double stopMs = stop / NORMALIZATION; |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 225 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 226 | return milli + "ms/" + startMs + '/' + stopMs; |
| 227 | } |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 228 | } |
Yuta HIGUCHI | a7188f2 | 2014-02-18 12:48:06 -0800 | [diff] [blame] | 229 | |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 230 | @Deprecated |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 231 | private static final PerformanceMonitor PERFORMANCE_MONITOR_INSTANCE = new PerformanceMonitor(); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 232 | |
| 233 | @Deprecated |
| 234 | public static Measurement start(String tag) { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 235 | return PERFORMANCE_MONITOR_INSTANCE.startStep(tag); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 236 | } |
| 237 | |
| 238 | @Deprecated |
| 239 | public static void stop(String tag) { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 240 | PERFORMANCE_MONITOR_INSTANCE.stopStep(tag); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 241 | } |
| 242 | |
| 243 | @Deprecated |
| 244 | public static void clear() { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 245 | PERFORMANCE_MONITOR_INSTANCE.reset(); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 246 | } |
| 247 | |
| 248 | @Deprecated |
| 249 | public static void report() { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 250 | PERFORMANCE_MONITOR_INSTANCE.reportAll(); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 251 | } |
| 252 | |
| 253 | @Deprecated |
| 254 | public static void report(String tag) { |
Ray Milkey | 5c9f2db | 2014-04-09 10:31:21 -0700 | [diff] [blame] | 255 | PERFORMANCE_MONITOR_INSTANCE.reportStep(tag); |
Yuta HIGUCHI | 8f28145 | 2014-02-18 16:08:04 -0800 | [diff] [blame] | 256 | } |
| 257 | |
Ray Milkey | 45614c5 | 2014-04-07 16:30:54 -0700 | [diff] [blame] | 258 | public static void main(String[] args) { |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 259 | // test the measurement overhead |
| 260 | String tag; |
| 261 | for (int i = 0; i < 2; i++) { |
| 262 | tag = "foo foo foo"; |
| 263 | Measurement m; |
| 264 | m = start(tag); |
| 265 | System.out.println(tag); |
| 266 | m.stop(); |
| 267 | m = start(tag); |
| 268 | System.out.println(tag); |
| 269 | m.stop(); |
| 270 | m = start(tag); |
| 271 | System.out.println(tag); |
| 272 | m.stop(); |
| 273 | m = start(tag); |
| 274 | System.out.println(tag); |
| 275 | m.stop(); |
| 276 | tag = "bar"; |
| 277 | start(tag); |
| 278 | stop(tag); |
| 279 | tag = "baz"; |
| 280 | start(tag); |
| 281 | stop(tag); |
| 282 | report(); |
| 283 | clear(); |
| 284 | } |
| 285 | for (int i = 0; i < 100; i++) { |
| 286 | tag = "a"; |
| 287 | start(tag); |
| 288 | stop(tag); |
| 289 | start(tag); |
| 290 | stop(tag); |
brian | 6df8823 | 2014-01-14 17:05:07 -0800 | [diff] [blame] | 291 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 292 | start(tag); |
| 293 | stop(tag); |
| 294 | start(tag); |
| 295 | stop(tag); |
| 296 | start(tag); |
| 297 | stop(tag); |
| 298 | start(tag); |
| 299 | stop(tag); |
| 300 | start(tag); |
| 301 | stop(tag); |
| 302 | start(tag); |
| 303 | stop(tag); |
brian | 6df8823 | 2014-01-14 17:05:07 -0800 | [diff] [blame] | 304 | |
Ray Milkey | 269ffb9 | 2014-04-03 14:43:30 -0700 | [diff] [blame] | 305 | tag = "b"; |
| 306 | start(tag); |
| 307 | stop(tag); |
| 308 | tag = "c"; |
| 309 | start(tag); |
| 310 | stop(tag); |
| 311 | report(); |
| 312 | clear(); |
| 313 | } |
Brian O'Connor | 8fdfb06 | 2014-01-08 17:47:57 -0800 | [diff] [blame] | 314 | } |
| 315 | } |