2013-08-28 19:24:34 -04:00
|
|
|
[[index-modules-slowlog]]
|
2015-06-22 17:49:45 -04:00
|
|
|
== Slow Log
|
2013-08-28 19:24:34 -04:00
|
|
|
|
|
|
|
[float]
|
2013-09-25 12:17:40 -04:00
|
|
|
[[search-slow-log]]
|
2013-08-28 19:24:34 -04:00
|
|
|
=== Search Slow Log
|
|
|
|
|
|
|
|
Shard level slow search log allows to log slow search (query and fetch
|
2015-06-22 17:49:45 -04:00
|
|
|
phases) into a dedicated log file.
|
2013-08-28 19:24:34 -04:00
|
|
|
|
|
|
|
Thresholds can be set for both the query phase of the execution, and
|
|
|
|
fetch phase, here is a sample:
|
|
|
|
|
2015-06-22 17:49:45 -04:00
|
|
|
[source,yaml]
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
2015-06-22 17:49:45 -04:00
|
|
|
index.search.slowlog.threshold.query.warn: 10s
|
|
|
|
index.search.slowlog.threshold.query.info: 5s
|
|
|
|
index.search.slowlog.threshold.query.debug: 2s
|
|
|
|
index.search.slowlog.threshold.query.trace: 500ms
|
|
|
|
|
|
|
|
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
|
2018-03-13 18:27:14 -04:00
|
|
|
|
|
|
|
index.search.slowlog.level: info
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
|
|
|
|
2019-06-21 09:24:33 -04:00
|
|
|
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:
|
|
|
|
|
2019-09-06 11:31:13 -04:00
|
|
|
[source,console]
|
2019-06-21 09:24:33 -04:00
|
|
|
--------------------------------------------------
|
|
|
|
PUT /twitter/_settings
|
|
|
|
{
|
|
|
|
"index.search.slowlog.threshold.query.warn": "10s",
|
|
|
|
"index.search.slowlog.threshold.query.info": "5s",
|
|
|
|
"index.search.slowlog.threshold.query.debug": "2s",
|
|
|
|
"index.search.slowlog.threshold.query.trace": "500ms",
|
|
|
|
"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"
|
|
|
|
}
|
|
|
|
--------------------------------------------------
|
|
|
|
// TEST[setup:twitter]
|
2015-06-22 17:49:45 -04:00
|
|
|
|
2013-08-28 19:24:34 -04:00
|
|
|
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.
|
|
|
|
|
|
|
|
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
|
|
|
|
search request, which can be broadcast to several shards in order to
|
|
|
|
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
|
2016-08-31 15:51:52 -04:00
|
|
|
configuration (found in `log4j2.properties`):
|
2013-08-28 19:24:34 -04:00
|
|
|
|
2016-10-17 10:50:32 -04:00
|
|
|
[source,properties]
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
2016-08-31 15:51:52 -04:00
|
|
|
appender.index_search_slowlog_rolling.type = RollingFile
|
|
|
|
appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
|
2017-11-15 04:01:32 -05:00
|
|
|
appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
|
2016-08-31 15:51:52 -04:00
|
|
|
appender.index_search_slowlog_rolling.layout.type = PatternLayout
|
2018-07-31 10:54:24 -04:00
|
|
|
appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
|
2017-11-15 04:01:32 -05:00
|
|
|
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
|
2016-08-31 15:51:52 -04:00
|
|
|
appender.index_search_slowlog_rolling.policies.type = Policies
|
2017-11-15 04:01:32 -05:00
|
|
|
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
|
2016-08-31 15:51:52 -04:00
|
|
|
|
|
|
|
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
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
|
|
|
|
2019-09-05 02:50:35 -04:00
|
|
|
[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.
|
|
|
|
[source,js]
|
|
|
|
---------------------------
|
|
|
|
{
|
|
|
|
"type": "index_search_slowlog",
|
|
|
|
"timestamp": "2030-08-30T11:59:37,786+02:00",
|
|
|
|
"level": "WARN",
|
|
|
|
"component": "i.s.s.query",
|
|
|
|
"cluster.name": "distribution_run",
|
|
|
|
"node.name": "node-0",
|
|
|
|
"message": "[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",
|
|
|
|
"cluster.uuid": "Aq-c-PAeQiK3tfBYtig9Bw",
|
|
|
|
"node.id": "D7fUYfnfTLa2D7y-xw6tZg"
|
|
|
|
}
|
|
|
|
---------------------------
|
|
|
|
// NOTCONSOLE
|
|
|
|
|
2013-08-28 19:24:34 -04:00
|
|
|
[float]
|
2013-09-25 12:17:40 -04:00
|
|
|
[[index-slow-log]]
|
2013-08-28 19:24:34 -04:00
|
|
|
=== Index Slow log
|
|
|
|
|
2014-04-15 00:55:39 -04:00
|
|
|
The indexing slow log, similar in functionality to the search slow
|
2016-06-21 07:20:23 -04:00
|
|
|
log. The log file name ends with `_index_indexing_slowlog.log`. Log and
|
2016-10-17 10:50:32 -04:00
|
|
|
the thresholds are configured in the same way as the search slowlog.
|
|
|
|
Index slowlog sample:
|
2013-08-28 19:24:34 -04:00
|
|
|
|
2015-06-22 17:49:45 -04:00
|
|
|
[source,yaml]
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
2015-06-22 17:49:45 -04:00
|
|
|
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
|
2015-08-11 16:13:43 -04:00
|
|
|
index.indexing.slowlog.level: info
|
|
|
|
index.indexing.slowlog.source: 1000
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
|
|
|
|
2019-06-21 09:24:33 -04:00
|
|
|
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:
|
|
|
|
|
2019-09-06 11:31:13 -04:00
|
|
|
[source,console]
|
2019-06-21 09:24:33 -04:00
|
|
|
--------------------------------------------------
|
|
|
|
PUT /twitter/_settings
|
|
|
|
{
|
|
|
|
"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"
|
|
|
|
}
|
|
|
|
--------------------------------------------------
|
|
|
|
// TEST[setup:twitter]
|
2015-06-22 17:49:45 -04:00
|
|
|
|
2015-08-11 16:13:43 -04:00
|
|
|
By default Elasticsearch will log the first 1000 characters of the _source in
|
|
|
|
the slowlog. You can change that with `index.indexing.slowlog.source`. Setting
|
|
|
|
it to `false` or `0` will skip logging the source entirely an setting it to
|
2016-11-28 13:12:43 -05:00
|
|
|
`true` will log the entire source regardless of size. The original `_source` is
|
|
|
|
reformatted by default to make sure that it fits on a single log line. If preserving
|
|
|
|
the original document format is important, you can turn off reformatting by setting
|
|
|
|
`index.indexing.slowlog.reformat` to `false`, which will cause the source to be
|
|
|
|
logged "as is" and can potentially span multiple log lines.
|
2015-08-11 16:13:43 -04:00
|
|
|
|
2016-10-17 10:50:32 -04:00
|
|
|
The index slow log file is configured by default in the `log4j2.properties`
|
2013-08-28 19:24:34 -04:00
|
|
|
file:
|
|
|
|
|
2016-10-17 10:50:32 -04:00
|
|
|
[source,properties]
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|
2016-10-17 10:50:32 -04:00
|
|
|
appender.index_indexing_slowlog_rolling.type = RollingFile
|
|
|
|
appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
|
2017-11-15 04:01:32 -05:00
|
|
|
appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
|
2016-10-17 10:50:32 -04:00
|
|
|
appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
|
2018-07-31 10:54:24 -04:00
|
|
|
appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
|
2017-11-15 04:01:32 -05:00
|
|
|
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
|
2016-10-17 10:50:32 -04:00
|
|
|
appender.index_indexing_slowlog_rolling.policies.type = Policies
|
2017-11-15 04:01:32 -05:00
|
|
|
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
|
2016-10-17 10:50:32 -04:00
|
|
|
|
|
|
|
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
|
2013-08-28 19:24:34 -04:00
|
|
|
--------------------------------------------------
|