Skip to content

Commit 70ab7b2

Browse files
weizijunweizijun
committed
add tests
1 parent b2c71a5 commit 70ab7b2

File tree

5 files changed

+194
-12
lines changed

5 files changed

+194
-12
lines changed

‎server/src/main/java/org/elasticsearch/index/SearchSlowLog.java‎

Lines changed: 7 additions & 10 deletions
Original file line numberDiff line numberDiff line change
@@ -190,16 +190,16 @@ public SearchSlowLog(IndexSettings indexSettings, SlowLogFields slowLogFields) {
190190

191191
indexSettings.getScopedSettings()
192192
.addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING, this::setDfsWarnThreshold);
193-
this.fetchWarnThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_WARN_SETTING).nanos();
193+
this.dfsWarnThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING).nanos();
194194
indexSettings.getScopedSettings()
195195
.addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING, this::setDfsInfoThreshold);
196-
this.fetchInfoThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_INFO_SETTING).nanos();
196+
this.dfsInfoThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING).nanos();
197197
indexSettings.getScopedSettings()
198198
.addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING, this::setDfsDebugThreshold);
199-
this.fetchDebugThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_DEBUG_SETTING).nanos();
199+
this.dfsDebugThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING).nanos();
200200
indexSettings.getScopedSettings()
201201
.addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING, this::setDfsTraceThreshold);
202-
this.fetchTraceThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_TRACE_SETTING).nanos();
202+
this.dfsTraceThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING).nanos();
203203
}
204204

205205
@Override
@@ -232,14 +232,11 @@ public void onFetchPhase(SearchContext context, long tookInNanos) {
232232
public void onDfsPhase(SearchContext context, long tookInNanos) {
233233
if (dfsWarnThreshold >= 0 && tookInNanos > dfsWarnThreshold) {
234234
dfsLogger.warn(SearchSlowLogMessage.of(this.slowLogFields.searchFields(), context, tookInNanos));
235-
}
236-
if (dfsInfoThreshold >= 0 && tookInNanos > dfsInfoThreshold) {
235+
} else if (dfsInfoThreshold >= 0 && tookInNanos > dfsInfoThreshold) {
237236
dfsLogger.info(SearchSlowLogMessage.of(this.slowLogFields.searchFields(), context, tookInNanos));
238-
}
239-
if (dfsDebugThreshold >= 0 && tookInNanos > dfsDebugThreshold) {
237+
} else if (dfsDebugThreshold >= 0 && tookInNanos > dfsDebugThreshold) {
240238
dfsLogger.debug(SearchSlowLogMessage.of(this.slowLogFields.searchFields(), context, tookInNanos));
241-
}
242-
if (dfsTraceThreshold >= 0 && tookInNanos > dfsTraceThreshold) {
239+
} else if (dfsTraceThreshold >= 0 && tookInNanos > dfsTraceThreshold) {
243240
dfsLogger.trace(SearchSlowLogMessage.of(this.slowLogFields.searchFields(), context, tookInNanos));
244241
}
245242
}

‎server/src/main/java/org/elasticsearch/index/shard/SearchOperationListener.java‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -184,6 +184,17 @@ public void onFetchPhase(SearchContext searchContext, long tookInNanos) {
184184
}
185185
}
186186

187+
@Override
188+
public void onDfsPhase(SearchContext context, long tookInNanos) {
189+
for (SearchOperationListener listener : listeners) {
190+
try {
191+
listener.onDfsPhase(context, tookInNanos);
192+
} catch (Exception e) {
193+
logger.warn(() -> "onDfsPhase listener [" + listener + "] failed", e);
194+
}
195+
}
196+
}
197+
187198
@Override
188199
public void onNewReaderContext(ReaderContext readerContext) {
189200
for (SearchOperationListener listener : listeners) {

‎server/src/main/java/org/elasticsearch/search/SearchService.java‎

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -577,7 +577,7 @@ private DfsSearchResult executeDfsPhase(ShardSearchRequest request, SearchShardT
577577
Releasable scope = tracer.withScope(task);
578578
Releasable ignored = readerContext.markAsUsed(getKeepAlive(request));
579579
SearchContext context = createContext(readerContext, request, task, ResultsType.DFS, false);
580-
SearchOperationListenerExecutor executor = new SearchOperationListenerExecutor(context)
580+
SearchOperationListenerExecutor executor = new SearchOperationListenerExecutor(context, false, true, System.nanoTime())
581581
) {
582582
DfsPhase.execute(context);
583583
executor.success();

‎server/src/test/java/org/elasticsearch/index/SearchSlowLogTests.java‎

Lines changed: 141 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,7 @@
2828
import org.elasticsearch.search.internal.ShardSearchRequest;
2929
import org.elasticsearch.tasks.CancellableTask;
3030
import org.elasticsearch.tasks.Task;
31+
import org.elasticsearch.tasks.TaskId;
3132
import org.elasticsearch.test.ESSingleNodeTestCase;
3233
import org.elasticsearch.test.TestSearchContext;
3334
import org.hamcrest.Matchers;
@@ -51,28 +52,34 @@ public class SearchSlowLogTests extends ESSingleNodeTestCase {
5152
static MockAppender appender;
5253
static Logger queryLog = LogManager.getLogger(SearchSlowLog.INDEX_SEARCH_SLOWLOG_PREFIX + ".query");
5354
static Logger fetchLog = LogManager.getLogger(SearchSlowLog.INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch");
55+
static Logger dfsLog = LogManager.getLogger(SearchSlowLog.INDEX_SEARCH_SLOWLOG_PREFIX + ".dfs");
5456
static Level origQueryLogLevel = queryLog.getLevel();
5557
static Level origFetchLogLevel = fetchLog.getLevel();
58+
static Level origDfsLogLevel = dfsLog.getLevel();
5659

5760
@BeforeClass
5861
public static void init() throws IllegalAccessException {
5962
appender = new MockAppender("trace_appender");
6063
appender.start();
6164
Loggers.addAppender(queryLog, appender);
6265
Loggers.addAppender(fetchLog, appender);
66+
Loggers.addAppender(dfsLog, appender);
6367

6468
Loggers.setLevel(queryLog, Level.TRACE);
6569
Loggers.setLevel(fetchLog, Level.TRACE);
70+
Loggers.setLevel(dfsLog, Level.TRACE);
6671
}
6772

6873
@AfterClass
6974
public static void cleanup() {
7075
Loggers.removeAppender(queryLog, appender);
7176
Loggers.removeAppender(fetchLog, appender);
77+
Loggers.removeAppender(dfsLog, appender);
7278
appender.stop();
7379

7480
Loggers.setLevel(queryLog, origQueryLogLevel);
7581
Loggers.setLevel(fetchLog, origFetchLogLevel);
82+
Loggers.setLevel(dfsLog, origDfsLogLevel);
7683
}
7784

7885
@Override
@@ -117,6 +124,11 @@ public void testLevelPrecedence() {
117124
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.INFO));
118125
log.onFetchPhase(ctx, 41L);
119126
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.WARN));
127+
128+
log.onDfsPhase(ctx, 40L);
129+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.INFO));
130+
log.onDfsPhase(ctx, 41L);
131+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.WARN));
120132
}
121133

122134
{
@@ -129,6 +141,12 @@ public void testLevelPrecedence() {
129141
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.DEBUG));
130142
log.onFetchPhase(ctx, 31L);
131143
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.INFO));
144+
145+
log.onDfsPhase(ctx, 30L);
146+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.DEBUG));
147+
log.onDfsPhase(ctx, 31L);
148+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.INFO));
149+
132150
}
133151

134152
{
@@ -141,6 +159,11 @@ public void testLevelPrecedence() {
141159
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.TRACE));
142160
log.onFetchPhase(ctx, 21L);
143161
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.DEBUG));
162+
163+
log.onDfsPhase(ctx, 20L);
164+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.TRACE));
165+
log.onDfsPhase(ctx, 21L);
166+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.DEBUG));
144167
}
145168

146169
{
@@ -153,6 +176,11 @@ public void testLevelPrecedence() {
153176
assertNull(appender.getLastEventAndReset());
154177
log.onFetchPhase(ctx, 11L);
155178
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.TRACE));
179+
180+
log.onDfsPhase(ctx, 10L);
181+
assertNull(appender.getLastEventAndReset());
182+
log.onDfsPhase(ctx, 11L);
183+
assertThat(appender.getLastEventAndReset().getLevel(), equalTo(Level.TRACE));
156184
}
157185
}
158186
}
@@ -169,7 +197,12 @@ private Settings.Builder settings(String uuid) {
169197
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING.getKey(), "10nanos")
170198
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING.getKey(), "20nanos")
171199
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING.getKey(), "30nanos")
172-
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40nanos");
200+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING.getKey(), "40nanos")
201+
202+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING.getKey(), "10nanos")
203+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING.getKey(), "20nanos")
204+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING.getKey(), "30nanos")
205+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING.getKey(), "40nanos");
173206
}
174207

175208
public void testTwoLoggersDifferentLevel() {
@@ -524,6 +557,113 @@ public void testSetFetchLevels() {
524557
}
525558
}
526559

560+
public void testSetDfsLevels() {
561+
IndexMetadata metadata = newIndexMeta(
562+
"index",
563+
Settings.builder()
564+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING.getKey(), "100ms")
565+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING.getKey(), "200ms")
566+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING.getKey(), "300ms")
567+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING.getKey(), "400ms")
568+
.build()
569+
);
570+
571+
IndexSettings settings = new IndexSettings(metadata, Settings.EMPTY);
572+
SearchSlowLog log = new SearchSlowLog(settings, mock(SlowLogFields.class));
573+
assertEquals(TimeValue.timeValueMillis(100).nanos(), log.getDfsTraceThreshold());
574+
assertEquals(TimeValue.timeValueMillis(200).nanos(), log.getDfsDebugThreshold());
575+
assertEquals(TimeValue.timeValueMillis(300).nanos(), log.getDfsInfoThreshold());
576+
assertEquals(TimeValue.timeValueMillis(400).nanos(), log.getDfsWarnThreshold());
577+
578+
settings.updateIndexMetadata(
579+
newIndexMeta(
580+
"index",
581+
Settings.builder()
582+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING.getKey(), "120ms")
583+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING.getKey(), "220ms")
584+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING.getKey(), "320ms")
585+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING.getKey(), "420ms")
586+
.build()
587+
)
588+
);
589+
590+
assertEquals(TimeValue.timeValueMillis(120).nanos(), log.getDfsTraceThreshold());
591+
assertEquals(TimeValue.timeValueMillis(220).nanos(), log.getDfsDebugThreshold());
592+
assertEquals(TimeValue.timeValueMillis(320).nanos(), log.getDfsInfoThreshold());
593+
assertEquals(TimeValue.timeValueMillis(420).nanos(), log.getDfsWarnThreshold());
594+
595+
metadata = newIndexMeta("index", Settings.builder().put(IndexMetadata.SETTING_VERSION_CREATED, IndexVersion.current()).build());
596+
settings.updateIndexMetadata(metadata);
597+
log = new SearchSlowLog(settings, mock(SlowLogFields.class));
598+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsTraceThreshold());
599+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsDebugThreshold());
600+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsInfoThreshold());
601+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsWarnThreshold());
602+
603+
settings = new IndexSettings(metadata, Settings.EMPTY);
604+
log = new SearchSlowLog(settings, mock(SlowLogFields.class));
605+
606+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsTraceThreshold());
607+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsDebugThreshold());
608+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsInfoThreshold());
609+
assertEquals(TimeValue.timeValueMillis(-1).nanos(), log.getDfsWarnThreshold());
610+
611+
try {
612+
settings.updateIndexMetadata(
613+
newIndexMeta(
614+
"index",
615+
Settings.builder()
616+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_TRACE_SETTING.getKey(), "NOT A TIME VALUE")
617+
.build()
618+
)
619+
);
620+
fail();
621+
} catch (IllegalArgumentException ex) {
622+
assertTimeValueException(ex, "index.search.slowlog.threshold.dfs.trace");
623+
}
624+
625+
try {
626+
settings.updateIndexMetadata(
627+
newIndexMeta(
628+
"index",
629+
Settings.builder()
630+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_DEBUG_SETTING.getKey(), "NOT A TIME VALUE")
631+
.build()
632+
)
633+
);
634+
fail();
635+
} catch (IllegalArgumentException ex) {
636+
assertTimeValueException(ex, "index.search.slowlog.threshold.dfs.debug");
637+
}
638+
639+
try {
640+
settings.updateIndexMetadata(
641+
newIndexMeta(
642+
"index",
643+
Settings.builder()
644+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_INFO_SETTING.getKey(), "NOT A TIME VALUE")
645+
.build()
646+
)
647+
);
648+
} catch (IllegalArgumentException ex) {
649+
assertTimeValueException(ex, "index.search.slowlog.threshold.dfs.info");
650+
}
651+
652+
try {
653+
settings.updateIndexMetadata(
654+
newIndexMeta(
655+
"index",
656+
Settings.builder()
657+
.put(SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_DFS_WARN_SETTING.getKey(), "NOT A TIME VALUE")
658+
.build()
659+
)
660+
);
661+
fail();
662+
} catch (IllegalArgumentException ex) {
663+
assertTimeValueException(ex, "index.search.slowlog.threshold.dfs.warn");
664+
}
665+
}
666+
527667
private void assertTimeValueException(final IllegalArgumentException e, final String key) {
528668
final String expected = "illegal value can't update [" + key + "] from [-1] to [NOT A TIME VALUE]";
529669
assertThat(e, hasToString(containsString(expected)));

0 commit comments

Comments
 (0)