001/* 002// This software is subject to the terms of the Eclipse Public License v1.0 003// Agreement, available at the following URL: 004// http://www.eclipse.org/legal/epl-v10.html. 005// You must accept the terms of that agreement to use this software. 006// 007// Copyright (C) 2011-2013 Pentaho and others 008// All Rights Reserved. 009*/ 010package mondrian.olap; 011 012import mondrian.util.ArrayStack; 013 014import java.util.*; 015 016/** 017 * Provides hooks for recording timing information of components of Query 018 * execution. 019 * 020 * <p>NOTE: This class is experimental and subject to change/removal 021 * without notice. 022 * 023 * <p>Code that executes as part of a Query can call 024 * {@link QueryTiming#markStart(String)} 025 * before executing, and {@link QueryTiming#markEnd(String)} afterwards, or can 026 * track execution times manually and call 027 * {@link QueryTiming#markFull(String, long)}. 028 * 029 * <p>To read timing information, add a handler to the statement using 030 * {@link mondrian.server.Statement#enableProfiling} and implement the 031 * {@link mondrian.spi.ProfileHandler#explain(String, QueryTiming)} method. 032 * 033 * @author jbarnett 034 */ 035public class QueryTiming { 036 private boolean enabled; 037 private final ArrayStack<TimingInfo> currentTimings = 038 new ArrayStack<TimingInfo>(); 039 private final Map<String, List<StartEnd>> timings = 040 new HashMap<String, List<StartEnd>>(); 041 private final Map<String, DurationCount> fullTimings = 042 new HashMap<String, DurationCount>(); 043 044 /** 045 * Initializes (or re-initializes) a query timing, also setting whether 046 * enabled. All previous stats are removed. 047 * 048 * @param enabled Whether to collect stats in future 049 */ 050 public synchronized void init(boolean enabled) { 051 this.enabled = enabled; 052 currentTimings.clear(); 053 timings.clear(); 054 fullTimings.clear(); 055 } 056 057 public void done() { 058 } 059 060 /** 061 * Marks the start of a Query component's execution. 062 * 063 * @param name Name of the component 064 */ 065 public synchronized final void markStart(String name) { 066 if (enabled) { 067 markStartInternal(name); 068 } 069 } 070 071 /** 072 * Marks the end of a Query component's execution. 073 * 074 * @param name Name of the component 075 */ 076 public synchronized final void markEnd(String name) { 077 if (enabled) { 078 long tstamp = System.currentTimeMillis(); 079 markEndInternal(name, tstamp); 080 } 081 } 082 083 /** 084 * Marks the duration of a Query component's execution. 085 * 086 * @param name Name of the component 087 * @param duration Duration of the execution 088 */ 089 public synchronized final void markFull(String name, long duration) { 090 if (enabled) { 091 markFullInternal(name, duration); 092 } 093 } 094 095 private void markStartInternal(String name) { 096 currentTimings.push(new TimingInfo(name)); 097 } 098 099 private void markEndInternal(String name, long tstamp) { 100 if (currentTimings.isEmpty() 101 || !currentTimings.peek().name.equals(name)) 102 { 103 throw new IllegalStateException("end but no start for " + name); 104 } 105 TimingInfo finished = currentTimings.pop(); 106 assert finished.name.equals(name); 107 finished.markEnd(tstamp); 108 109 List<StartEnd> timingList = timings.get(finished.name); 110 if (timingList == null) { 111 timingList = new ArrayList<StartEnd>(); 112 timings.put(finished.name, timingList); 113 } 114 timingList.add(new StartEnd(finished.startTime, finished.endTime)); 115 } 116 117 private void markFullInternal(String name, long duration) { 118 DurationCount p = fullTimings.get(name); 119 if (p == null) { 120 p = new DurationCount(); 121 fullTimings.put(name, p); 122 } 123 p.count++; 124 p.duration += duration; 125 } 126 127 public synchronized String toString() { 128 StringBuilder sb = new StringBuilder(); 129 for (Map.Entry<String, List<StartEnd>> entry 130 : timings.entrySet()) 131 { 132 if (sb.length() > 0) { 133 sb.append(Util.nl); 134 } 135 long total = 0; 136 for (StartEnd durection : entry.getValue()) { 137 total += (durection.endTime - durection.startTime); 138 } 139 int count = entry.getValue().size(); 140 sb.append(entry.getKey()) 141 .append(" invoked ") 142 .append(count) 143 .append(" times for total of ") 144 .append(total) 145 .append("ms. (Avg. ") 146 .append(total / count) 147 .append("ms/invocation)"); 148 } 149 for (Map.Entry<String, DurationCount> entry 150 : fullTimings.entrySet()) 151 { 152 if (sb.length() > 0) { 153 sb.append(Util.nl); 154 } 155 sb.append(entry.getKey()) 156 .append(" invoked ") 157 .append(entry.getValue().count) 158 .append(" times for total of ") 159 .append(entry.getValue().duration) 160 .append("ms. (Avg. ") 161 .append(entry.getValue().duration / entry.getValue().count) 162 .append("ms/invocation)"); 163 } 164 return sb.toString(); 165 } 166 167 /** 168 * @return a collection of all Query component names 169 */ 170 public synchronized Collection<String> getTimingKeys() { 171 Set<String> keys = new HashSet<String>(); 172 keys.addAll(timings.keySet()); 173 keys.addAll(fullTimings.keySet()); 174 return keys; 175 } 176 177 /** 178 * @param key Name of the Query component to get timing information on 179 * @return a List of durations 180 */ 181 public synchronized List<Long> getTimings(String key) { 182 List<Long> timingList = new ArrayList<Long>(); 183 List<StartEnd> regTime = timings.get(key); 184 if (regTime != null) { 185 for (StartEnd timing : regTime) { 186 timingList.add(timing.endTime - timing.startTime); 187 } 188 } 189 DurationCount qTime = fullTimings.get(key); 190 if (qTime != null) { 191 final Long duration = qTime.duration; 192 for (int i = 0; i < qTime.count; i++) { 193 timingList.add(duration); 194 } 195 } 196 return timingList; 197 } 198 199 private static class TimingInfo { 200 private final String name; 201 private final long startTime; 202 private long endTime; 203 204 private TimingInfo(String name) { 205 this.name = name; 206 this.startTime = System.currentTimeMillis(); 207 } 208 209 private void markEnd(long tstamp) { 210 this.endTime = tstamp; 211 } 212 } 213 214 private static class StartEnd { 215 final long startTime; 216 final long endTime; 217 218 public StartEnd(long startTime, long endTime) { 219 this.startTime = startTime; 220 this.endTime = endTime; 221 } 222 } 223 224 private static class DurationCount { 225 long duration; 226 long count; 227 } 228} 229 230// End QueryTiming.java