slowlog.asciidoc 8.3 KB

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