slowlog.asciidoc 8.3 KB

123456789101112131415161718192021222324252627282930313233343536373839404142434445464748495051525354555657585960616263646566676869707172737475767778798081828384858687888990919293949596979899100101102103104105106107108109110111112113114115116117118119120121122123124125126127128129130131132133134135136137138139140141142143144145146147148149150151152153154155156157158159160161162163164165166167168169170171172173174175176177178179180181182183184185186
  1. [[index-modules-slowlog]]
  2. == Slow Log
  3. [float]
  4. [[search-slow-log]]
  5. === Search Slow Log
  6. Shard level slow search log allows to log slow search (query and fetch
  7. phases) into a dedicated log file.
  8. Thresholds can be set for both the query phase of the execution, and
  9. fetch phase, here is a sample:
  10. [source,yaml]
  11. --------------------------------------------------
  12. index.search.slowlog.threshold.query.warn: 10s
  13. index.search.slowlog.threshold.query.info: 5s
  14. index.search.slowlog.threshold.query.debug: 2s
  15. index.search.slowlog.threshold.query.trace: 500ms
  16. index.search.slowlog.threshold.fetch.warn: 1s
  17. index.search.slowlog.threshold.fetch.info: 800ms
  18. index.search.slowlog.threshold.fetch.debug: 500ms
  19. index.search.slowlog.threshold.fetch.trace: 200ms
  20. index.search.slowlog.level: info
  21. --------------------------------------------------
  22. All of the above settings are _dynamic_ and can be set for each index using the
  23. <<indices-update-settings, update indices settings>> API. For example:
  24. [source,console]
  25. --------------------------------------------------
  26. PUT /twitter/_settings
  27. {
  28. "index.search.slowlog.threshold.query.warn": "10s",
  29. "index.search.slowlog.threshold.query.info": "5s",
  30. "index.search.slowlog.threshold.query.debug": "2s",
  31. "index.search.slowlog.threshold.query.trace": "500ms",
  32. "index.search.slowlog.threshold.fetch.warn": "1s",
  33. "index.search.slowlog.threshold.fetch.info": "800ms",
  34. "index.search.slowlog.threshold.fetch.debug": "500ms",
  35. "index.search.slowlog.threshold.fetch.trace": "200ms",
  36. "index.search.slowlog.level": "info"
  37. }
  38. --------------------------------------------------
  39. // TEST[setup:twitter]
  40. By default, none are enabled (set to `-1`). Levels (`warn`, `info`,
  41. `debug`, `trace`) allow to control under which logging level the log
  42. will be logged. Not all are required to be configured (for example, only
  43. `warn` threshold can be set). The benefit of several levels is the
  44. ability to quickly "grep" for specific thresholds breached.
  45. The logging is done on the shard level scope, meaning the execution of a
  46. search request within a specific shard. It does not encompass the whole
  47. search request, which can be broadcast to several shards in order to
  48. execute. Some of the benefits of shard level logging is the association
  49. of the actual execution on the specific machine, compared with request
  50. level.
  51. The logging file is configured by default using the following
  52. configuration (found in `log4j2.properties`):
  53. [source,properties]
  54. --------------------------------------------------
  55. appender.index_search_slowlog_rolling.type = RollingFile
  56. appender.index_search_slowlog_rolling.name = index_search_slowlog_rolling
  57. appender.index_search_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_search_slowlog.log
  58. appender.index_search_slowlog_rolling.layout.type = PatternLayout
  59. appender.index_search_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
  60. 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
  61. appender.index_search_slowlog_rolling.policies.type = Policies
  62. appender.index_search_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
  63. appender.index_search_slowlog_rolling.policies.size.size = 1GB
  64. appender.index_search_slowlog_rolling.strategy.type = DefaultRolloverStrategy
  65. appender.index_search_slowlog_rolling.strategy.max = 4
  66. logger.index_search_slowlog_rolling.name = index.search.slowlog
  67. logger.index_search_slowlog_rolling.level = trace
  68. logger.index_search_slowlog_rolling.appenderRef.index_search_slowlog_rolling.ref = index_search_slowlog_rolling
  69. logger.index_search_slowlog_rolling.additivity = false
  70. --------------------------------------------------
  71. [float]
  72. ==== Identifying search slow log origin
  73. 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
  74. is included in Search Slow logs as an additional **id** field (scroll to the right).
  75. [source,txt]
  76. ---------------------------
  77. [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],
  78. ---------------------------
  79. // NOTCONSOLE
  80. The user ID is also included in JSON logs.
  81. [source,js]
  82. ---------------------------
  83. {
  84. "type": "index_search_slowlog",
  85. "timestamp": "2030-08-30T11:59:37,786+02:00",
  86. "level": "WARN",
  87. "component": "i.s.s.query",
  88. "cluster.name": "distribution_run",
  89. "node.name": "node-0",
  90. "message": "[index6][0]",
  91. "took": "78.4micros",
  92. "took_millis": "0",
  93. "total_hits": "0 hits",
  94. "stats": "[]",
  95. "search_type": "QUERY_THEN_FETCH",
  96. "total_shards": "1",
  97. "source": "{\"query\":{\"match_all\":{\"boost\":1.0}}}",
  98. "id": "MY_USER_ID",
  99. "cluster.uuid": "Aq-c-PAeQiK3tfBYtig9Bw",
  100. "node.id": "D7fUYfnfTLa2D7y-xw6tZg"
  101. }
  102. ---------------------------
  103. // NOTCONSOLE
  104. [float]
  105. [[index-slow-log]]
  106. === Index Slow log
  107. The indexing slow log, similar in functionality to the search slow
  108. log. The log file name ends with `_index_indexing_slowlog.log`. Log and
  109. the thresholds are configured in the same way as the search slowlog.
  110. Index slowlog sample:
  111. [source,yaml]
  112. --------------------------------------------------
  113. index.indexing.slowlog.threshold.index.warn: 10s
  114. index.indexing.slowlog.threshold.index.info: 5s
  115. index.indexing.slowlog.threshold.index.debug: 2s
  116. index.indexing.slowlog.threshold.index.trace: 500ms
  117. index.indexing.slowlog.level: info
  118. index.indexing.slowlog.source: 1000
  119. --------------------------------------------------
  120. All of the above settings are _dynamic_ and can be set for each index using the
  121. <<indices-update-settings, update indices settings>> API. For example:
  122. [source,console]
  123. --------------------------------------------------
  124. PUT /twitter/_settings
  125. {
  126. "index.indexing.slowlog.threshold.index.warn": "10s",
  127. "index.indexing.slowlog.threshold.index.info": "5s",
  128. "index.indexing.slowlog.threshold.index.debug": "2s",
  129. "index.indexing.slowlog.threshold.index.trace": "500ms",
  130. "index.indexing.slowlog.level": "info",
  131. "index.indexing.slowlog.source": "1000"
  132. }
  133. --------------------------------------------------
  134. // TEST[setup:twitter]
  135. By default Elasticsearch will log the first 1000 characters of the _source in
  136. the slowlog. You can change that with `index.indexing.slowlog.source`. Setting
  137. it to `false` or `0` will skip logging the source entirely an setting it to
  138. `true` will log the entire source regardless of size. The original `_source` is
  139. reformatted by default to make sure that it fits on a single log line. If preserving
  140. the original document format is important, you can turn off reformatting by setting
  141. `index.indexing.slowlog.reformat` to `false`, which will cause the source to be
  142. logged "as is" and can potentially span multiple log lines.
  143. The index slow log file is configured by default in the `log4j2.properties`
  144. file:
  145. [source,properties]
  146. --------------------------------------------------
  147. appender.index_indexing_slowlog_rolling.type = RollingFile
  148. appender.index_indexing_slowlog_rolling.name = index_indexing_slowlog_rolling
  149. appender.index_indexing_slowlog_rolling.fileName = ${sys:es.logs.base_path}${sys:file.separator}${sys:es.logs.cluster_name}_index_indexing_slowlog.log
  150. appender.index_indexing_slowlog_rolling.layout.type = PatternLayout
  151. appender.index_indexing_slowlog_rolling.layout.pattern = [%d{ISO8601}][%-5p][%-25c] [%node_name]%marker %.-10000m%n
  152. 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
  153. appender.index_indexing_slowlog_rolling.policies.type = Policies
  154. appender.index_indexing_slowlog_rolling.policies.size.type = SizeBasedTriggeringPolicy
  155. appender.index_indexing_slowlog_rolling.policies.size.size = 1GB
  156. appender.index_indexing_slowlog_rolling.strategy.type = DefaultRolloverStrategy
  157. appender.index_indexing_slowlog_rolling.strategy.max = 4
  158. logger.index_indexing_slowlog.name = index.indexing.slowlog.index
  159. logger.index_indexing_slowlog.level = trace
  160. logger.index_indexing_slowlog.appenderRef.index_indexing_slowlog_rolling.ref = index_indexing_slowlog_rolling
  161. logger.index_indexing_slowlog.additivity = false
  162. --------------------------------------------------