// Copyright Yahoo. Licensed under the terms of the Apache 2.0 license. See LICENSE in the project root. package com.yahoo.search.statistics; import com.yahoo.component.chain.Chain; import com.yahoo.prelude.Pong; import com.yahoo.processing.Processor; import com.yahoo.search.Result; import com.yahoo.search.Searcher; import java.util.ArrayList; import java.util.EnumMap; import java.util.List; import java.util.Map; /** * A container for storing time stamps throughout the lifetime of an Execution instance. * *

Check state both when entering and exiting, to allow for arbitrary * new queries anywhere inside a search chain. * * @author Steinar Knutsen */ public final class TimeTracker { public enum Activity { PING, SEARCH, FILL; } static class SearcherTimer { // Searcher ID private final String name; // Time spent transforming query/producing result private final EnumMap invoking = new EnumMap<>(Activity.class); // Time spent transforming result private final EnumMap returning = new EnumMap<>(Activity.class); SearcherTimer(String name) { this.name = name; } private void activityRepr(StringBuilder buffer, int preLen, Map.Entry m) { if (buffer.length() != preLen) { buffer.append(", "); } buffer.append(m.getKey()).append(": ").append(m.getValue()) .append(" ms"); } void addInvoking(Activity activity, long time) { Long storedTillNow = invoking.get(activity); long tillNow = getTime(storedTillNow); invoking.put(activity, Long.valueOf(tillNow + time)); } void addReturning(Activity activity, long time) { Long storedTillNow = returning.get(activity); long tillNow = getTime(storedTillNow); returning.put(activity, Long.valueOf(tillNow + time)); } Long getInvoking(Activity activity) { return invoking.get(activity); } String getName() { return name; } Long getReturning(Activity activity) { return returning.get(activity); } private long getTime(Long storedTillNow) { long tillNow; if (storedTillNow == null) { tillNow = 0L; } else { tillNow = storedTillNow.longValue(); } return tillNow; } public void merge(SearcherTimer other) { for (Map.Entry invokingEntry : other.invoking.entrySet()) { addInvoking(invokingEntry.getKey(), invokingEntry.getValue()); } for (Map.Entry returningEntry : other.returning.entrySet()) { addReturning(returningEntry.getKey(), returningEntry.getValue()); } } public String toString() { StringBuilder buffer = new StringBuilder(); int preLen; buffer.append(name).append("(").append("QueryProcessing("); preLen = buffer.length(); for (Map.Entry m : invoking.entrySet()) { activityRepr(buffer, preLen, m); } buffer.append("), ResultProcessing("); preLen = buffer.length(); for (Map.Entry m : returning.entrySet()) { activityRepr(buffer, preLen, m); } buffer.append("))"); return buffer.toString(); } } static class State { public final long start; public final Activity activity; State(long start, Activity activity) { super(); this.start = start; this.activity = activity; } } static class Tag { public final long start; public final long end; public final Activity activity; Tag(long start, long end, Activity activity) { super(); this.start = start; this.end = end; this.activity = activity; } } static class TimeSource { long now() { return System.currentTimeMillis(); } } private State state = null; private List tags = new ArrayList<>(); private SearcherTimer[] searcherTracking = null; private final Chain searchChain; // whether the previous state was invoking or returning private boolean invoking = true; private long last = 0L; private final int entryIndex; TimeSource timeSource = new TimeSource(); public TimeTracker(Chain searchChain) { this(searchChain, 0); } public TimeTracker(Chain searchChain, int entryIndex) { this.searchChain = searchChain; this.entryIndex = entryIndex; } private void concludeState(long now) { if (state == null) { return; } tags.add(new Tag(state.start, now, state.activity)); state = null; } private void concludeStateOnExit(long now) { if (now != 0L) { concludeState(now); } else { concludeState(getNow()); } } private long detailedMeasurements(int searcherIndex, boolean calledAsInvoking) { long now = getNow(); if (searcherTracking == null) { initBreakdown(); } SearcherTimer timeSpentIn = getPreviouslyRunSearcher(searcherIndex, calledAsInvoking); long spent = now - last; if (timeSpentIn != null && last != 0L) { if (invoking) { timeSpentIn.addInvoking(getActivity(), spent); } else { timeSpentIn.addReturning(getActivity(), spent); } } last = now; if (searcherIndex >= searcherTracking.length) { // We are now outside the search chain and will go back up with the // default result. invoking = false; } else { invoking = calledAsInvoking; } return now; } private void enteringState(int searcherIndex, boolean detailed, final Activity activity) { long now = 0L; if (detailed) { now = detailedMeasurements(searcherIndex, true); } if (isNewState(activity)) { if (now == 0L) { now = getNow(); } concludeState(now); initNewState(now, activity); } } private long fetchTime(Activity filter, Tag container) { if (filter == container.activity) { return container.end - container.start; } else { return 0L; } } public long fillTime() { return typedSum(Activity.FILL); } public long first() { if (tags.isEmpty()) { return 0L; } else { return tags.get(0).start; } } public long firstFill() { for (Tag t : tags) { if (t.activity == Activity.FILL) { return t.start; } } return 0L; } private Activity getActivity() { if (state == null) { throw new IllegalStateException("Trying to measure an interval having only one point."); } return state.activity; } private long getNow() { return timeSource.now(); } private SearcherTimer getPreviouslyRunSearcher(int searcherIndex, boolean calledAsInvoking) { if (calledAsInvoking) { searcherIndex -= 1; if (searcherIndex < entryIndex) { return null; } else { return searcherTracking[searcherIndex]; } } else { return searcherTracking[searcherIndex]; } } private void initBreakdown() { if (searcherTracking != null) { throw new IllegalStateException("initBreakdown invoked" + " when measurement structures are already initialized."); } List searchers = searchChain.components(); searcherTracking = new SearcherTimer[searchers.size()]; for (int i = 0; i < searcherTracking.length; ++i) { searcherTracking[i] = new SearcherTimer(searchers.get(i).getId().stringValue()); } } private void initNewState(long now, Activity activity) { state = new State(now, activity); } void injectTimeSource(TimeSource source) { this.timeSource = source; } private boolean isNewState(Activity callPath) { if (state == null) { return true; } else if (callPath == state.activity) { return false; } else { return true; } } public long last() { if (tags.isEmpty()) { return 0L; } else { return tags.get(tags.size() - 1).end; } } public long pingTime() { return typedSum(Activity.PING); } private long returnFromState(int searcherIndex, boolean detailed) { if (detailed) { return detailedMeasurements(searcherIndex, false); } else { return 0L; } } public void sampleFill(int searcherIndex, boolean detailed) { enteringState(searcherIndex, detailed, Activity.FILL); } public void sampleFillReturn(int searcherIndex, boolean detailed, Result annotationReference) { ElapsedTime elapsed = getElapsedTime(annotationReference); sampleReturn(searcherIndex, detailed, elapsed); } public void samplePing(int searcherIndex, boolean detailed) { enteringState(searcherIndex, detailed, Activity.PING); } public void samplePingReturn(int searcherIndex, boolean detailed, Pong annotationReference) { ElapsedTime elapsed = getElapsedTime(annotationReference); sampleReturn(searcherIndex, detailed, elapsed); } public void sampleSearch(int searcherIndex, boolean detailed) { enteringState(searcherIndex, detailed, Activity.SEARCH); } public void sampleSearchReturn(int searcherIndex, boolean detailed, Result annotationReference) { ElapsedTime elapsed = getElapsedTime(annotationReference); sampleReturn(searcherIndex, detailed, elapsed); } private void sampleReturn(int searcherIndex, boolean detailed, ElapsedTime elapsed) { long now = returnFromState(searcherIndex, detailed); if (searcherIndex == entryIndex) { concludeStateOnExit(now); if (elapsed != null) { elapsed.add(this); } } } private ElapsedTime getElapsedTime(Result r) { return r == null ? null : r.getElapsedTime(); } private ElapsedTime getElapsedTime(Pong p) { return p == null ? null : p.getElapsedTime(); } SearcherTimer[] searcherTracking() { return searcherTracking; } public long searchTime() { return typedSum(Activity.SEARCH); } public long totalTime() { return last() - first(); } private long typedSum(Activity activity) { long sum = 0L; for (Tag tag : tags) { sum += fetchTime(activity, tag); } return sum; } }