Skip to content

Commit

Permalink
Add total_hits, shards to slow log
Browse files Browse the repository at this point in the history 
Signed-off-by: David Zane <[email protected]>
  • Loading branch information
@dzane17
dzane17 committed Oct 30, 2023
1 parent 13f1cbf commit 3868868
Show file tree
Hide file tree
Showing 6 changed files with 171 additions and 38 deletions.
6 changes: 3 additions & 3 deletions distribution/src/config/log4j2.properties
View file
Original file line number Diff line number Diff line change
Expand Up @@ -113,15 +113,15 @@ logger.deprecation.appenderRef.deprecation_rolling_old.ref = deprecation_rolling
logger.deprecation.appenderRef.header_warning.ref = header_warning
logger.deprecation.additivity = false

######## Search Request slowlog JSON ####################
######## Search Request Slowlog JSON ####################
appender.search_request_slowlog_json_appender.type = RollingFile
appender.search_request_slowlog_json_appender.name = search_request_slowlog_json_appender
appender.search_request_slowlog_json_appender.fileName = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs\
.cluster_name}_index_search_slowlog.json
appender.search_request_slowlog_json_appender.filePermissions = rw-r-----
appender.search_request_slowlog_json_appender.layout.type = OpenSearchJsonLayout
appender.search_request_slowlog_json_appender.layout.type_name = search_request_slowlog
appender.search_request_slowlog_json_appender.layout.opensearchmessagefields=message,took,took_millis,phase_took,search_type,total_shards,source,id
appender.search_request_slowlog_json_appender.layout.opensearchmessagefields=message,took,took_millis,phase_took,total_hits,search_type,shards,source,id

appender.search_request_slowlog_json_appender.filePattern = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs\
.cluster_name}_index_search_slowlog-%i.json.gz
Expand All @@ -131,7 +131,7 @@ appender.search_request_slowlog_json_appender.policies.size.size = 1GB
appender.search_request_slowlog_json_appender.strategy.type = DefaultRolloverStrategy
appender.search_request_slowlog_json_appender.strategy.max = 4
#################################################
######## Search slowlog - old style pattern ####
######## Search Request Slowlog Log File - old style pattern ####
appender.search_request_slowlog_log_appender.type = RollingFile
appender.search_request_slowlog_log_appender.name = search_request_slowlog_log_appender
appender.search_request_slowlog_log_appender.fileName = ${sys:opensearch.logs.base_path}${sys:file.separator}${sys:opensearch.logs.cluster_name}\
Expand Down
27 changes: 20 additions & 7 deletions server/src/main/java/org/opensearch/action/search/AbstractSearchAsyncAction.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -436,20 +436,20 @@ public final void executeNextPhase(SearchPhase currentPhase, SearchPhase nextPha
}

private void onPhaseEnd(SearchRequestContext searchRequestContext) {
this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> {
searchRequestOperations.onPhaseEnd(this, searchRequestContext);
});
this.searchRequestOperationsListener.ifPresent(
searchRequestOperations -> searchRequestOperations.onPhaseEnd(this, searchRequestContext)
);
}

private void onPhaseStart(SearchPhase phase) {
setCurrentPhase(phase);
this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> { searchRequestOperations.onPhaseStart(this); });
this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> searchRequestOperations.onPhaseStart(this));
}

private void onRequestEnd(SearchRequestContext searchRequestContext) {
this.searchRequestOperationsListener.ifPresent(searchRequestOperations -> {
searchRequestOperations.onRequestEnd(this, searchRequestContext);
});
this.searchRequestOperationsListener.ifPresent(
searchRequestOperations -> searchRequestOperations.onRequestEnd(this, searchRequestContext)
);
}

private void executePhase(SearchPhase phase) {
Expand Down Expand Up @@ -707,6 +707,19 @@ public void sendSearchResponse(InternalSearchResponse internalSearchResponse, At
searchContextId = null;
}
}
searchRequestContext.setTotalHits(internalSearchResponse.hits().getTotalHits());
searchRequestContext.setShardStats(
Map.of(
"total",
results.getNumShards(),
"successful",
successfulOps.get(),
"skipped",
skippedOps.get(),
"failed",
failures.length
)
);
onPhaseEnd(searchRequestContext);
onRequestEnd(searchRequestContext);
listener.onResponse(buildSearchResponse(internalSearchResponse, failures, scrollId, searchContextId));
Expand Down
44 changes: 44 additions & 0 deletions server/src/main/java/org/opensearch/action/search/SearchRequestContext.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -8,6 +8,8 @@

package org.opensearch.action.search;

import org.apache.lucene.search.TotalHits;

import java.util.HashMap;
import java.util.Map;

Expand All @@ -19,9 +21,12 @@
public class SearchRequestContext {
private long absoluteStartNanos;
private final Map<String, Long> phaseTookMap;
private TotalHits totalHits;
private Map<String, Integer> shardStats;

public SearchRequestContext() {
this.phaseTookMap = new HashMap<>();
this.totalHits = null;
}

protected void updatePhaseTookMap(String phaseName, Long tookTime) {
Expand All @@ -40,4 +45,43 @@ protected long absoluteStartNanos() {
return absoluteStartNanos;
}

protected void setTotalHits(TotalHits totalHits) {
this.totalHits = totalHits;
}

protected TotalHits totalHits() {
return totalHits;
}

protected void setShardStats(Map<String, Integer> shardStats) {
this.shardStats = shardStats;
}

protected Map<String, Integer> shardStats() {
return shardStats;
}

public final String SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL = "total";
public final String SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL = "successful";
public final String SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED = "skipped";
public final String SEARCH_REQUEST_SLOWLOG_SHARD_FAILED = "failed";

protected String formattedShardStats() {
if (shardStats != null) {
return String.format(
"{%s: %s, %s: %s, %s: %s, %s: %s}",
SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL,
shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_TOTAL),
SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL,
shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_SUCCESSFUL),
SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED,
shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_SKIPPED),
SEARCH_REQUEST_SLOWLOG_SHARD_FAILED,
shardStats.get(SEARCH_REQUEST_SLOWLOG_SHARD_FAILED)
);
} else {
return "{}";
}

}
}
39 changes: 26 additions & 13 deletions server/src/main/java/org/opensearch/action/search/SearchRequestSlowLog.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -151,13 +151,13 @@ public void onRequestEnd(SearchPhaseContext context, SearchRequestContext search
long tookInNanos = System.nanoTime() - searchRequestContext.absoluteStartNanos();

if (warnThreshold >= 0 && tookInNanos > warnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
logger.warn(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap()));
logger.warn(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext));
} else if (infoThreshold >= 0 && tookInNanos > infoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
logger.info(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap()));
logger.info(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext));
} else if (debugThreshold >= 0 && tookInNanos > debugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
logger.debug(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap()));
logger.debug(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext));
} else if (traceThreshold >= 0 && tookInNanos > traceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
logger.trace(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext.phaseTookMap()));
logger.trace(new SearchRequestSlowLogMessage(context, tookInNanos, searchRequestContext));
}
}

Expand All @@ -168,21 +168,29 @@ public void onRequestEnd(SearchPhaseContext context, SearchRequestContext search
*/
static final class SearchRequestSlowLogMessage extends OpenSearchLogMessage {

SearchRequestSlowLogMessage(SearchPhaseContext context, long tookInNanos, Map<String, Long> phaseTookMap) {
super(prepareMap(context, tookInNanos, phaseTookMap), message(context, tookInNanos, phaseTookMap));
SearchRequestSlowLogMessage(SearchPhaseContext context, long tookInNanos, SearchRequestContext searchRequestContext) {
super(prepareMap(context, tookInNanos, searchRequestContext), message(context, tookInNanos, searchRequestContext));
}

private static Map<String, Object> prepareMap(SearchPhaseContext context, long tookInNanos, Map<String, Long> phaseTookMap) {
private static Map<String, Object> prepareMap(
SearchPhaseContext context,
long tookInNanos,
SearchRequestContext searchRequestContext
) {
final Map<String, Object> messageFields = new HashMap<>();
messageFields.put("took", TimeValue.timeValueNanos(tookInNanos));
messageFields.put("took_millis", TimeUnit.NANOSECONDS.toMillis(tookInNanos));
messageFields.put("phase_took", phaseTookMap);
messageFields.put("phase_took", searchRequestContext.phaseTookMap().toString());
if (searchRequestContext.totalHits() != null) {
messageFields.put("total_hits", searchRequestContext.totalHits());
} else {
messageFields.put("total_hits", "-1");
}
messageFields.put("search_type", context.getRequest().searchType());
messageFields.put("total_shards", context.getNumShards());
messageFields.put("shards", searchRequestContext.formattedShardStats());

if (context.getRequest().source() != null) {
String source = escapeJson(context.getRequest().source().toString(FORMAT_PARAMS));

messageFields.put("source", source);
} else {
messageFields.put("source", "{}");
Expand All @@ -193,13 +201,18 @@ private static Map<String, Object> prepareMap(SearchPhaseContext context, long t
}

// Message will be used in plaintext logs
private static String message(SearchPhaseContext context, long tookInNanos, Map<String, Long> phaseTookMap) {
private static String message(SearchPhaseContext context, long tookInNanos, SearchRequestContext searchRequestContext) {
final StringBuilder sb = new StringBuilder();
sb.append("took[").append(TimeValue.timeValueNanos(tookInNanos)).append("], ");
sb.append("took_millis[").append(TimeUnit.NANOSECONDS.toMillis(tookInNanos)).append("], ");
sb.append("phase_took_millis[").append(phaseTookMap.toString()).append("], ");
sb.append("phase_took_millis[").append(searchRequestContext.phaseTookMap().toString()).append("], ");
if (searchRequestContext.totalHits() != null) {
sb.append("total_hits[").append(searchRequestContext.totalHits()).append("], ");
} else {
sb.append("total_hits[-1]");
}
sb.append("search_type[").append(context.getRequest().searchType()).append("], ");
sb.append("total_shards[").append(context.getNumShards()).append("], ");
sb.append("shards[").append(searchRequestContext.formattedShardStats()).append("], ");
if (context.getRequest().source() != null) {
sb.append("source[").append(context.getRequest().source().toString(FORMAT_PARAMS)).append("], ");
} else {
Expand Down
7 changes: 6 additions & 1 deletion server/src/main/java/org/opensearch/action/search/TransportSearchAction.java
View file
Original file line number Diff line number Diff line change
Expand Up @@ -1257,7 +1257,12 @@ private List<SearchRequestOperationsListener> createSearchListenerList(SearchReq
searchListenersList.add(timeProvider);
}

searchListenersList.add(searchRequestSlowLog);
if (searchRequestSlowLog.getWarnThreshold() >= 0
&& searchRequestSlowLog.getInfoThreshold() >= 0
&& searchRequestSlowLog.getDebugThreshold() >= 0
&& searchRequestSlowLog.getTraceThreshold() >= 0) {
searchListenersList.add(searchRequestSlowLog);
}

return searchListenersList;
}
Expand Down
Loading

0 comments on commit 3868868

Please sign in to comment.