// 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.ComponentId; import com.yahoo.component.chain.Chain; import com.yahoo.search.Query; import com.yahoo.search.Result; import com.yahoo.search.Searcher; import com.yahoo.search.result.Hit; import com.yahoo.search.searchchain.Execution; import com.yahoo.search.statistics.TimeTracker.Activity; import com.yahoo.search.statistics.TimeTracker.SearcherTimer; import org.junit.jupiter.api.Test; import static org.junit.jupiter.api.Assertions.*; /** * Check sanity of TimeTracker and ElapsedTime. * * @author Steinar Knutsen */ public class ElapsedTimeTestCase { private static final long[] SEARCH_TIMESEQUENCE = new long[] { 1L, 2L, 3L, 4L, 5L, 6L, 7L }; private static final long[] SEARCH_AND_FILL_TIMESEQUENCE = new long[] { 1L, 2L, 3L, 4L, 5L, 6L, 7L, // and here we start filling 7L, 8L, 9L, 10L, 11L, 12L, 13L }; public static class CreativeTimeSource extends TimeTracker.TimeSource { private int nowIndex = 0; private long[] now; public CreativeTimeSource(long[] now) { this.now = now; } @Override long now() { long present = now[nowIndex++]; if (present == 0L) { // defensive coding against the innards of TimeTracker throw new IllegalStateException("0 is an unsupported time stamp value."); } return present; } } public static class UselessSearcher extends Searcher { public UselessSearcher(String name) { super(new ComponentId(name)); } @Override public Result search(Query query, Execution execution) { return execution.search(query); } } private static class AlmostUselessSearcher extends Searcher { AlmostUselessSearcher(String name) { super(new ComponentId(name)); } @Override public Result search(Query query, Execution execution) { Result r = execution.search(query); Hit h = new Hit("nalle"); h.setFillable(); r.hits().add(h); return r; } } private static class NoForwardSearcher extends Searcher { @Override public Result search(Query query, Execution execution) { Result r = new Result(query); Hit h = new Hit("nalle"); h.setFillable(); r.hits().add(h); return r; } } private class TestingSearcher extends Searcher { @Override public Result search(Query query, Execution execution) { Execution exec = new Execution(execution); exec.timer().injectTimeSource( new CreativeTimeSource(SEARCH_TIMESEQUENCE)); exec.context().setDetailedDiagnostics(true); Result r = exec.search(new Query()); SearcherTimer[] searchers = exec.timer().searcherTracking(); assertNull(searchers[0].getInvoking(Activity.SEARCH)); checkTiming(searchers, 1); return r; } } private class SecondTestingSearcher extends Searcher { @Override public Result search(Query query, Execution execution) { Execution exec = new Execution(execution); exec.timer().injectTimeSource( new CreativeTimeSource(SEARCH_AND_FILL_TIMESEQUENCE)); exec.context().setDetailedDiagnostics(true); Result result = exec.search(new Query()); exec.fill(result); SearcherTimer[] searchers = exec.timer().searcherTracking(); assertNull(searchers[0].getInvoking(Activity.SEARCH)); checkTiming(searchers, 1); assertNull(searchers[0].getInvoking(Activity.FILL)); checkFillTiming(searchers, 1); return result; } } private class ShortChainTestingSearcher extends Searcher { @Override public Result search(Query query, Execution execution) { Execution exec = new Execution(execution); exec.timer().injectTimeSource( new CreativeTimeSource(new long[] { 1L, 2L, 2L })); exec.context().setDetailedDiagnostics(true); Result result = exec.search(new Query()); SearcherTimer[] searchers = exec.timer().searcherTracking(); assertNull(searchers[0].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1].getInvoking(Activity.SEARCH)); assertNull(searchers[1].getReturning(Activity.SEARCH)); assertNull(searchers[0].getInvoking(Activity.FILL)); assertNull(searchers[1].getInvoking(Activity.FILL)); assertTrue(0 < result.getElapsedTime().detailedReport().indexOf("NoForwardSearcher")); return result; } } @Test void testBasic() { TimeTracker t = new TimeTracker(null); t.injectTimeSource(new CreativeTimeSource(new long[]{1L, 2L, 3L, 4L})); Query q = new Query(); Result r = new Result(q); t.sampleSearch(0, false); t.sampleFill(0, false); t.samplePing(0, false); t.sampleSearchReturn(0, false, r); assertEquals(1L, t.first()); assertEquals(4L, t.last()); assertEquals(2L, t.firstFill()); assertEquals(1L, t.searchTime()); assertEquals(1L, t.fillTime()); assertEquals(1L, t.pingTime()); assertEquals(3L, t.totalTime()); } @Test void testMultiSearchAndPing() { TimeTracker t = new TimeTracker(null); t.injectTimeSource(new CreativeTimeSource(new long[]{1L, 4L, 16L, 32L, 64L, 128L, 256L})); Query q = new Query(); Result r = new Result(q); t.sampleSearch(0, false); t.samplePing(0, false); t.sampleSearch(0, false); t.samplePing(0, false); t.sampleSearch(0, false); t.sampleFill(0, false); t.sampleSearchReturn(0, false, r); assertEquals(1L, t.first()); assertEquals(256L, t.last()); assertEquals(128L, t.firstFill()); assertEquals(83L, t.searchTime()); assertEquals(128L, t.fillTime()); assertEquals(44L, t.pingTime()); assertEquals(255L, t.totalTime()); ElapsedTime e = new ElapsedTime(); e.add(t); e.add(t); // multiple adds is supposed to be safe assertEquals(255L, t.totalTime()); TimeTracker tx = new TimeTracker(null); tx.injectTimeSource(new CreativeTimeSource(new long[]{1L, 2L, 3L, 4L})); Query qx = new Query(); Result rx = new Result(qx); tx.sampleSearch(0, false); tx.sampleFill(0, false); tx.samplePing(0, false); tx.sampleSearchReturn(0, false, rx); e.add(tx); assertEquals(258L, e.totalTime()); assertEquals(129L, e.fillTime()); assertEquals(2L, e.firstFill()); } @Test void testBasicBreakdown() { TimeTracker t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); t.injectTimeSource(new CreativeTimeSource(new long[]{1L, 2L, 3L, 4L, 5L, 6L, 7L})); t.sampleSearch(0, true); t.sampleSearch(1, true); t.sampleSearch(2, true); t.sampleSearch(3, true); t.sampleSearchReturn(2, true, null); t.sampleSearchReturn(1, true, null); t.sampleSearchReturn(0, true, null); SearcherTimer[] searchers = t.searcherTracking(); checkTiming(searchers); } // This test is to make sure the other tests correctly simulate the call // order into the TimeTracker @Test void testBasicBreakdownFullyWiredIn() { Chain chain = new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third")); Execution exec = new Execution(chain, Execution.Context.createContextStub()); exec.timer().injectTimeSource(new CreativeTimeSource(SEARCH_TIMESEQUENCE)); exec.context().setDetailedDiagnostics(true); exec.search(new Query()); SearcherTimer[] searchers = exec.timer().searcherTracking(); checkTiming(searchers); } private void checkTiming(SearcherTimer[] searchers) { checkTiming(searchers, 0); } private void checkTiming(SearcherTimer[] searchers, int offset) { assertEquals(Long.valueOf(1L), searchers[0 + offset].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1 + offset].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[2 + offset].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[2 + offset].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1 + offset].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[0 + offset].getReturning(Activity.SEARCH)); } @Test void testBasicBreakdownWithFillFullyWiredIn() { Chain chain = new Chain<>( new UselessSearcher("first"), new UselessSearcher("second"), new AlmostUselessSearcher("third")); Execution exec = new Execution(chain, Execution.Context.createContextStub()); exec.timer().injectTimeSource( new CreativeTimeSource(SEARCH_AND_FILL_TIMESEQUENCE)); exec.context().setDetailedDiagnostics(true); Result result = exec.search(new Query()); exec.fill(result); SearcherTimer[] searchers = exec.timer().searcherTracking(); checkTiming(searchers); checkFillTiming(searchers); } private void checkFillTiming(SearcherTimer[] searchers) { checkFillTiming(searchers, 0); } private void checkFillTiming(SearcherTimer[] searchers, int offset) { assertEquals(Long.valueOf(1L), searchers[0 + offset].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[1 + offset].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[2 + offset].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[2 + offset].getReturning(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[1 + offset].getReturning(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[0 + offset].getReturning(Activity.FILL)); } @Test void testBasicBreakdownFullyWiredInFirstSearcherNotFirstInChain() { Chain chain = new Chain<>( new TestingSearcher(), new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third")); Execution exec = new Execution(chain, Execution.Context.createContextStub()); exec.search(new Query()); } @Test void testBasicBreakdownWithFillFullyWiredInFirstSearcherNotFirstInChain() { Chain chain = new Chain<>( new SecondTestingSearcher(), new UselessSearcher("first"), new UselessSearcher("second"), new AlmostUselessSearcher("third")); Execution exec = new Execution(chain, Execution.Context.createContextStub()); exec.search(new Query()); } @Test void testTimingWithShortChain() { Chain chain = new Chain<>( new ShortChainTestingSearcher(), new NoForwardSearcher()); Execution exec = new Execution(chain, Execution.Context.createContextStub()); exec.search(new Query()); } @Test void testBasicBreakdownReturnInsideSearchChain() { TimeTracker t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); t.injectTimeSource(new CreativeTimeSource(new long[]{1L, 2L, 3L, 4L, 5L, 6L})); t.sampleSearch(0, true); t.sampleSearch(1, true); t.sampleSearch(2, true); t.sampleSearchReturn(2, true, null); t.sampleSearchReturn(1, true, null); t.sampleSearchReturn(0, true, null); SearcherTimer[] searchers = t.searcherTracking(); assertEquals(Long.valueOf(1L), searchers[0].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[2].getInvoking(Activity.SEARCH)); assertNull(searchers[2].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[0].getReturning(Activity.SEARCH)); } @Test void testBasicBreakdownWithFill() { TimeTracker t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); t.injectTimeSource(new CreativeTimeSource(new long[]{1L, 2L, 3L, 4L, 5L, 6L, 7L, 7L, 8L, 9L, 10L})); t.sampleSearch(0, true); t.sampleSearch(1, true); t.sampleSearch(2, true); t.sampleSearch(3, true); t.sampleSearchReturn(2, true, null); t.sampleSearchReturn(1, true, null); t.sampleSearchReturn(0, true, null); t.sampleFill(0, true); t.sampleFill(1, true); t.sampleFillReturn(1, true, null); t.sampleFillReturn(0, true, null); SearcherTimer[] searchers = t.searcherTracking(); assertEquals(Long.valueOf(1L), searchers[0].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[2].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[2].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[1].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[0].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(1L), searchers[0].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[1].getInvoking(Activity.FILL)); assertNull(searchers[1].getReturning(Activity.FILL)); assertEquals(Long.valueOf(1L), searchers[0].getReturning(Activity.FILL)); } private void runSomeTraffic(TimeTracker t) { t.injectTimeSource(new CreativeTimeSource(new long[] { 1L, 2L, 3L, // checkpoint 1 4L, 5L, // checkpoint 2 6L, 7L, 8L, 9L, // checkpoint 3 10L, 11L, 12L, 13L, // checkpoint 4 14L, 15L, 16L, 17L, // checkpoint 5 18L })); t.sampleSearch(0, true); t.sampleSearch(1, true); t.sampleSearch(2, true); // checkpoint 1 t.sampleSearchReturn(2, true, null); t.sampleSearchReturn(1, true, null); // checkpoint 2 t.sampleFill(1, true); t.sampleFill(2, true); t.sampleFillReturn(2, true, null); t.sampleFillReturn(1, true, null); // checkpoint 3 t.sampleSearch(1, true); t.sampleSearch(2, true); t.sampleSearchReturn(2, true, null); t.sampleSearchReturn(1, true, null); // checkpoint 4 t.sampleFill(1, true); t.sampleFill(2, true); t.sampleFillReturn(2, true, null); t.sampleFillReturn(1, true, null); // checkpoint 5 t.sampleSearchReturn(0, true, null); } @Test void testMixedActivity() { TimeTracker t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); runSomeTraffic(t); SearcherTimer[] searchers = t.searcherTracking(); assertEquals(Long.valueOf(1L), searchers[0].getInvoking(Activity.SEARCH)); assertNull(searchers[0].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(2L), searchers[0].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(2L), searchers[0].getReturning(Activity.FILL)); assertEquals(Long.valueOf(2L), searchers[1].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(2L), searchers[1].getInvoking(Activity.FILL)); assertEquals(Long.valueOf(2L), searchers[1].getReturning(Activity.SEARCH)); assertEquals(Long.valueOf(2L), searchers[1].getReturning(Activity.FILL)); assertEquals(Long.valueOf(2L), searchers[2].getInvoking(Activity.SEARCH)); assertEquals(Long.valueOf(2L), searchers[2].getInvoking(Activity.FILL)); assertNull(searchers[2].getReturning(Activity.SEARCH)); assertNull(searchers[2].getReturning(Activity.FILL)); } @Test void testReportGeneration() { TimeTracker t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); runSomeTraffic(t); ElapsedTime elapsed = new ElapsedTime(); elapsed.add(t); t = new TimeTracker(new Chain( new UselessSearcher("first"), new UselessSearcher("second"), new UselessSearcher("third"))); runSomeTraffic(t); elapsed.add(t); assertEquals(true, elapsed.hasDetailedData()); assertEquals("Time use per searcher:" + " first(QueryProcessing(SEARCH: 2 ms), ResultProcessing(SEARCH: 4 ms, FILL: 4 ms)),\n" + " second(QueryProcessing(SEARCH: 4 ms, FILL: 4 ms), ResultProcessing(SEARCH: 4 ms, FILL: 4 ms)),\n" + " third(QueryProcessing(SEARCH: 4 ms, FILL: 4 ms), ResultProcessing()).", elapsed.detailedReport()); } public static void doInjectTimeSource(TimeTracker t, TimeTracker.TimeSource s) { t.injectTimeSource(s); } }