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