Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

Remove slowlog level #57591

Merged
merged 8 commits into from
Jun 4, 2020
Merged

Remove slowlog level #57591

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
8 commits
Select commit Hold shift + click to select a range
6ed838c
draft remove slow log level
pgomulka Jun 2, 2020
27a35c1
remove slow log level
pgomulka Jun 3, 2020
f91804b
fix docs
pgomulka Jun 3, 2020
cd62089
remove comma
pgomulka Jun 3, 2020
cb21423
breaking changes
pgomulka Jun 3, 2020
851a820
javadoc and highlights
pgomulka Jun 4, 2020
58cb6e8
Merge branch 'master' into remove-slowlog-level
elasticmachine Jun 4, 2020
04886af
Merge branch 'master' into remove-slowlog-level
elasticmachine Jun 4, 2020
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
73 changes: 9 additions & 64 deletions docs/reference/index-modules/slowlog.asciidoc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -22,12 +22,10 @@ index.search.slowlog.threshold.fetch.warn: 1s
index.search.slowlog.threshold.fetch.info: 800ms
index.search.slowlog.threshold.fetch.debug: 500ms
index.search.slowlog.threshold.fetch.trace: 200ms

index.search.slowlog.level: info
--------------------------------------------------

All of the above settings are _dynamic_ and can be set for each index using the
<<indices-update-settings, update indices settings>> API. For example:
<<indices-update-settings, update indices settings>> API. For example:

[source,console]
--------------------------------------------------
Expand All @@ -40,17 +38,12 @@ PUT /twitter/_settings
"index.search.slowlog.threshold.fetch.warn": "1s",
"index.search.slowlog.threshold.fetch.info": "800ms",
"index.search.slowlog.threshold.fetch.debug": "500ms",
"index.search.slowlog.threshold.fetch.trace": "200ms",
"index.search.slowlog.level": "info"
"index.search.slowlog.threshold.fetch.trace": "200ms"
}
--------------------------------------------------
// TEST[setup:twitter]

By default, none are enabled (set to `-1`). Levels (`warn`, `info`,
`debug`, `trace`) allow to control under which logging level the log
will be logged. Not all are required to be configured (for example, only
`warn` threshold can be set). The benefit of several levels is the
ability to quickly "grep" for specific thresholds breached.
By default thresholds are disabled (set to `-1`).

The logging is done on the shard level scope, meaning the execution of a
search request within a specific shard. It does not encompass the whole
Expand All @@ -59,40 +52,15 @@ execute. Some of the benefits of shard level logging is the association
of the actual execution on the specific machine, compared with request
level.

The logging file is configured by default using the following
configuration (found in `log4j2.properties`):

[source,properties]
--------------------------------------------------
appender.index_search_slowlog_rolling.type = RollingFile
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
appender.index_search_slowlog_rolling.layout.type = PatternLayout
appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
appender.index_search_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog-%i.log.gz
appender.index_search_slowlog_rolling.policies.type = Policies
appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_search_slowlog_rolling.policies.size.size = 1GB
appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_search_slowlog_rolling.strategy.max = 4

logger.index_search_slowlog_rolling.name = index.search.slowlog
logger.index_search_slowlog_rolling.level = trace
logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
logger.index_search_slowlog_rolling.additivity = false
--------------------------------------------------
The search slow log file is configured in the `log4j2.properties` file.

[float]
==== Identifying search slow log origin

It is often useful to identify what triggered a slow running query. If a call was initiated with an `X-Opaque-ID` header, then the user ID
is included in Search Slow logs as an additional **id** field (scroll to the right).
[source,txt]
---------------------------
[2030-08-30T11:59:37,786][WARN ][i.s.s.query ] [node-0] [index6][0] took[78.4micros], took_millis[0], total_hits[0 hits], stats[], search_type[QUERY_THEN_FETCH], total_shards[1], source[{"query":{"match_all":{"boost":1.0}}}], id[MY_USER_ID],
---------------------------
// NOTCONSOLE
The user ID is also included in JSON logs.
is included in Search Slow logs as an additional **id** field

[source,js]
---------------------------
{
Expand Down Expand Up @@ -122,7 +90,7 @@ The user ID is also included in JSON logs.
=== Index Slow log

The indexing slow log, similar in functionality to the search slow
log. The log file name ends with `_index_indexing_slowlog.log`. Log and
log. The log file name ends with `_index_indexing_slowlog.json`. Log and
the thresholds are configured in the same way as the search slowlog.
Index slowlog sample:

Expand All @@ -132,12 +100,11 @@ index.indexing.slowlog.threshold.index.warn: 10s
index.indexing.slowlog.threshold.index.info: 5s
index.indexing.slowlog.threshold.index.debug: 2s
index.indexing.slowlog.threshold.index.trace: 500ms
index.indexing.slowlog.level: info
index.indexing.slowlog.source: 1000
--------------------------------------------------

All of the above settings are _dynamic_ and can be set for each index using the
<<indices-update-settings, update indices settings>> API. For example:
<<indices-update-settings, update indices settings>> API. For example:

[source,console]
--------------------------------------------------
Expand All @@ -147,7 +114,6 @@ PUT /twitter/_settings
"index.indexing.slowlog.threshold.index.info": "5s",
"index.indexing.slowlog.threshold.index.debug": "2s",
"index.indexing.slowlog.threshold.index.trace": "500ms",
"index.indexing.slowlog.level": "info",
"index.indexing.slowlog.source": "1000"
}
--------------------------------------------------
Expand All @@ -162,25 +128,4 @@ the original document format is important, you can turn off reformatting by sett
`index.indexing.slowlog.reformat` to `false`, which will cause the source to be
logged "as is" and can potentially span multiple log lines.

The index slow log file is configured by default in the `log4j2.properties`
file:

[source,properties]
--------------------------------------------------
appender.index_indexing_slowlog_rolling.type = RollingFile
appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
appender.index_indexing_slowlog_rolling.filePattern = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog-%i.log.gz
appender.index_indexing_slowlog_rolling.policies.type = Policies
appender.index_indexing_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
appender.index_indexing_slowlog_rolling.policies.size.size = 1GB
appender.index_indexing_slowlog_rolling.strategy.type = DefaultRolloverStrategy
appender.index_indexing_slowlog_rolling.strategy.max = 4

logger.index_indexing_slowlog.name = index.indexing.slowlog.index
logger.index_indexing_slowlog.level = trace
logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling
logger.index_indexing_slowlog.additivity = false
--------------------------------------------------
The index slow log file is configured in the `log4j2.properties` file.
7 changes: 7 additions & 0 deletions docs/reference/release-notes/8.0.0-alpha1.asciidoc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,4 +18,11 @@ Mapping::
Deprecations::
* Remove undocumented endpoints of hot threads API {pull}55109[#55109]

Slow loggers::
* `index.indexing.slowlog.level` and `index.search.slowlog.level` are removed. These settings can be worked around
by using appropriate thresholds. If for instance we want to simulate `index.indexing.slowlog.level` = `INFO` then
all we need to do is to set `index.indexing.slowlog.threshold.index.debug` and
`index.indexing.slowlog.threshold.index.trace` to `-1` {pull}57591[#57591]


coming[8.0.0]
2 changes: 0 additions & 2 deletions server/src/main/java/org/elasticsearch/common/settings/IndexScopedSettings.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -88,12 +88,10 @@ public final class IndexScopedSettings extends AbstractScopedSettings {
SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_DEBUG_SETTING,
SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_INFO_SETTING,
SearchSlowLog.INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_TRACE_SETTING,
SearchSlowLog.INDEX_SEARCH_SLOWLOG_LEVEL,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_WARN_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_DEBUG_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_INFO_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_LEVEL_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING,
IndexingSlowLog.INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING,
MergePolicyConfig.INDEX_COMPOUND_FORMAT_SETTING,
Expand Down
26 changes: 6 additions & 20 deletions server/src/main/java/org/elasticsearch/index/IndexingSlowLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -19,6 +19,7 @@

package org.elasticsearch.index;

import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.apache.logging.log4j.util.StringBuilders;
Expand Down Expand Up @@ -58,9 +59,6 @@ public final class IndexingSlowLog implements IndexingOperationListener {
TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
public static final Setting<Boolean> INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING =
Setting.boolSetting(INDEX_INDEXING_SLOWLOG_PREFIX +".reformat", true, Property.Dynamic, Property.IndexScope);
public static final Setting<SlowLogLevel> INDEX_INDEXING_SLOWLOG_LEVEL_SETTING =
new Setting<>(INDEX_INDEXING_SLOWLOG_PREFIX +".level", SlowLogLevel.TRACE.name(), SlowLogLevel::parse, Property.Dynamic,
Property.IndexScope);

private final Logger indexLogger;
private final Index index;
Expand All @@ -75,7 +73,6 @@ public final class IndexingSlowLog implements IndexingOperationListener {
* <em>characters</em> of the source.
*/
private int maxSourceCharsToLog;
private SlowLogLevel level;

/**
* Reads how much of the source to log. The user can specify any value they
Expand All @@ -94,7 +91,7 @@ public final class IndexingSlowLog implements IndexingOperationListener {

IndexingSlowLog(IndexSettings indexSettings) {
this.indexLogger = LogManager.getLogger(INDEX_INDEXING_SLOWLOG_PREFIX + ".index");
Loggers.setLevel(this.indexLogger, SlowLogLevel.TRACE.name());
Loggers.setLevel(this.indexLogger, Level.TRACE);
this.index = indexSettings.getIndex();

indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_REFORMAT_SETTING, this::setReformat);
Expand All @@ -111,8 +108,6 @@ public final class IndexingSlowLog implements IndexingOperationListener {
indexSettings.getScopedSettings()
.addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING, this::setTraceThreshold);
this.indexTraceThreshold = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_THRESHOLD_INDEX_TRACE_SETTING).nanos();
indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_LEVEL_SETTING, this::setLevel);
setLevel(indexSettings.getValue(INDEX_INDEXING_SLOWLOG_LEVEL_SETTING));
indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING,
this::setMaxSourceCharsToLog);
this.maxSourceCharsToLog = indexSettings.getValue(INDEX_INDEXING_SLOWLOG_MAX_SOURCE_CHARS_TO_LOG_SETTING);
Expand All @@ -122,10 +117,6 @@ private void setMaxSourceCharsToLog(int maxSourceCharsToLog) {
this.maxSourceCharsToLog = maxSourceCharsToLog;
}

private void setLevel(SlowLogLevel level) {
this.level = level;
}

private void setWarnThreshold(TimeValue warnThreshold) {
this.indexWarnThreshold = warnThreshold.nanos();
}
Expand All @@ -151,14 +142,13 @@ public void postIndex(ShardId shardId, Engine.Index indexOperation, Engine.Index
if (result.getResultType() == Engine.Result.Type.SUCCESS) {
final ParsedDocument doc = indexOperation.parsedDoc();
final long tookInNanos = result.getTook();
// when logger level is more specific than WARN AND event is within threshold it should be logged
if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
if (indexWarnThreshold >= 0 && tookInNanos > indexWarnThreshold) {
indexLogger.warn(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
} else if (indexInfoThreshold >= 0 && tookInNanos > indexInfoThreshold) {
indexLogger.info(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
} else if (indexDebugThreshold >= 0 && tookInNanos > indexDebugThreshold) {
indexLogger.debug(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
} else if (indexTraceThreshold >= 0 && tookInNanos > indexTraceThreshold) {
indexLogger.trace(IndexingSlowLogMessage.of(index, doc, tookInNanos, reformat, maxSourceCharsToLog));
}
}
Expand Down Expand Up @@ -232,8 +222,4 @@ int getMaxSourceCharsToLog() {
return maxSourceCharsToLog;
}

SlowLogLevel getLevel() {
return level;
}

}
35 changes: 11 additions & 24 deletions server/src/main/java/org/elasticsearch/index/SearchSlowLog.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -20,6 +20,7 @@
package org.elasticsearch.index;

import com.fasterxml.jackson.core.io.JsonStringEncoder;
import org.apache.logging.log4j.Level;
import org.apache.logging.log4j.LogManager;
import org.apache.logging.log4j.Logger;
import org.elasticsearch.common.logging.ESLogMessage;
Expand Down Expand Up @@ -80,18 +81,14 @@ public final class SearchSlowLog implements SearchOperationListener {
public static final Setting<TimeValue> INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_TRACE_SETTING =
Setting.timeSetting(INDEX_SEARCH_SLOWLOG_PREFIX + ".threshold.fetch.trace", TimeValue.timeValueNanos(-1),
TimeValue.timeValueMillis(-1), Property.Dynamic, Property.IndexScope);
public static final Setting<SlowLogLevel> INDEX_SEARCH_SLOWLOG_LEVEL =
new Setting<>(INDEX_SEARCH_SLOWLOG_PREFIX + ".level", SlowLogLevel.TRACE.name(), SlowLogLevel::parse, Property.Dynamic,
Property.IndexScope);

private static final ToXContent.Params FORMAT_PARAMS = new ToXContent.MapParams(Collections.singletonMap("pretty", "false"));
private SlowLogLevel level;

public SearchSlowLog(IndexSettings indexSettings) {
this.queryLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".query");
this.fetchLogger = LogManager.getLogger(INDEX_SEARCH_SLOWLOG_PREFIX + ".fetch");
Loggers.setLevel(this.fetchLogger, SlowLogLevel.TRACE.name());
Loggers.setLevel(this.queryLogger, SlowLogLevel.TRACE.name());
Loggers.setLevel(this.fetchLogger, Level.TRACE);
Loggers.setLevel(this.queryLogger, Level.TRACE);

indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_QUERY_WARN_SETTING,
this::setQueryWarnThreshold);
Expand All @@ -118,37 +115,30 @@ public SearchSlowLog(IndexSettings indexSettings) {
indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_TRACE_SETTING,
this::setFetchTraceThreshold);
this.fetchTraceThreshold = indexSettings.getValue(INDEX_SEARCH_SLOWLOG_THRESHOLD_FETCH_TRACE_SETTING).nanos();

indexSettings.getScopedSettings().addSettingsUpdateConsumer(INDEX_SEARCH_SLOWLOG_LEVEL, this::setLevel);
setLevel(indexSettings.getValue(INDEX_SEARCH_SLOWLOG_LEVEL));
}

private void setLevel(SlowLogLevel level) {
this.level = level;
}

@Override
public void onQueryPhase(SearchContext context, long tookInNanos) {
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
if (queryWarnThreshold >= 0 && tookInNanos > queryWarnThreshold) {
queryLogger.warn(SearchSlowLogMessage.of(context, tookInNanos));
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
} else if (queryInfoThreshold >= 0 && tookInNanos > queryInfoThreshold) {
queryLogger.info(SearchSlowLogMessage.of(context, tookInNanos));
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
} else if (queryDebugThreshold >= 0 && tookInNanos > queryDebugThreshold) {
queryLogger.debug(SearchSlowLogMessage.of(context, tookInNanos));
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
} else if (queryTraceThreshold >= 0 && tookInNanos > queryTraceThreshold) {
queryLogger.trace(SearchSlowLogMessage.of(context, tookInNanos));
}
}

@Override
public void onFetchPhase(SearchContext context, long tookInNanos) {
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold && level.isLevelEnabledFor(SlowLogLevel.WARN)) {
if (fetchWarnThreshold >= 0 && tookInNanos > fetchWarnThreshold) {
fetchLogger.warn(SearchSlowLogMessage.of(context, tookInNanos));
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold && level.isLevelEnabledFor(SlowLogLevel.INFO)) {
} else if (fetchInfoThreshold >= 0 && tookInNanos > fetchInfoThreshold) {
fetchLogger.info(SearchSlowLogMessage.of(context, tookInNanos));
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold && level.isLevelEnabledFor(SlowLogLevel.DEBUG)) {
} else if (fetchDebugThreshold >= 0 && tookInNanos > fetchDebugThreshold) {
fetchLogger.debug(SearchSlowLogMessage.of(context, tookInNanos));
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold && level.isLevelEnabledFor(SlowLogLevel.TRACE)) {
} else if (fetchTraceThreshold >= 0 && tookInNanos > fetchTraceThreshold) {
fetchLogger.trace(SearchSlowLogMessage.of(context, tookInNanos));
}
}
Expand Down Expand Up @@ -257,7 +247,4 @@ long getFetchTraceThreshold() {
return fetchTraceThreshold;
}

SlowLogLevel getLevel() {
return level;
}
}
43 changes: 0 additions & 43 deletions server/src/main/java/org/elasticsearch/index/SlowLogLevel.java
View file
Open in desktop

This file was deleted.

Loading