Support Percona extended slow log (#10227)

Fix #6665 Co-authored-by: Hagen Montag <[email protected]>
elastic · Jan 22, 2019 · 84844b3 · 84844b3
1 parent 73bc50e
commit 84844b3
Show file tree

Hide file tree

Showing 9 changed files with 487 additions and 10 deletions.
diff --git a/CHANGELOG.next.asciidoc b/CHANGELOG.next.asciidoc
@@ -162,6 +162,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
 - HAProxy module now populates `event.duration` and `http.response.bytes` (ECS). {pull}10143[10143]
 - Teach elasticsearch/audit fileset to parse out some more fields. {issue}10134[10134] {pull}10137[10137]
 - Add convert_timezone to nginx module. {issue}9839[9839] {pull}10148[10148]
+- Add support for Percona in the `slowlog` fileset of `mysql` module. {issue}6665[6665] {pull}10227[10227]
 
 *Heartbeat*
 

diff --git a/filebeat/docs/fields.asciidoc b/filebeat/docs/fields.asciidoc
@@ -6443,6 +6443,18 @@ type: long
 The number of rows modified by the query.
 
 
+--
+
+*`mysql.slowlog.bytes_sent`*::
++
+--
+type: long
+
+format: bytes
+
+The size of the query result.
+
+
 --
 
 *`mysql.slowlog.query`*::
@@ -6480,6 +6492,26 @@ type: keyword
 Current authenticated user, used to determine access privileges. Can differ from the value for user.
 
 
+--
+
+*`mysql.slowlog.last_errno`*::
++
+--
+type: keyword
+
+Last SQL error seen.
+
+
+--
+
+*`mysql.slowlog.killed`*::
++
+--
+type: keyword
+
+Code of the reason if the query was killed.
+
+
 --
 
 *`mysql.slowlog.query_cache_hit`*::
@@ -6510,6 +6542,37 @@ type: boolean
 Whether the query needed temporary tables on disk.
 
 
+--
+
+*`mysql.slowlog.tmp_tables`*::
++
+--
+type: long
+
+Number of temporary tables created for this query
+
+
+--
+
+*`mysql.slowlog.tmp_disk_tables`*::
++
+--
+type: long
+
+Number of temporary tables created on disk for this query.
+
+
+--
+
+*`mysql.slowlog.tmp_table_sizes`*::
++
+--
+type: long
+
+format: bytes
+
+Size of temporary tables created for this query.
+
 --
 
 *`mysql.slowlog.filesort`*::
@@ -6570,6 +6633,105 @@ type: long
 Number of merge passes executed for the query.
 
 
+--
+
+*`mysql.slowlog.log_slow_rate_type`*::
++
+--
+type: keyword
+
+Type of slow log rate limit, it can be `session` if the rate limit is applied per session, or `query` if it applies per query.
+
+
+--
+
+*`mysql.slowlog.log_slow_rate_limit`*::
++
+--
+type: keyword
+
+Slow log rate limit, a value of 100 means that one in a hundred queries or sessions are being logged.
+
+
+--
+
+[float]
+== innodb fields
+
+Contains fields relative to InnoDB engine
+
+
+
+*`mysql.slowlog.innodb.trx_id`*::
++
+--
+type: keyword
+
+Transaction ID
+
+
+--
+
+*`mysql.slowlog.innodb.io_r_ops`*::
++
+--
+type: long
+
+Number of page read operations.
+
+
+--
+
+*`mysql.slowlog.innodb.io_r_bytes`*::
++
+--
+type: long
+
+format: bytes
+
+Bytes read during page read operations.
+
+
+--
+
+*`mysql.slowlog.innodb.io_r_wait.sec`*::
++
+--
+type: long
+
+How long it took to read all needed data from storage.
+
+
+--
+
+*`mysql.slowlog.innodb.rec_lock_wait.sec`*::
++
+--
+type: long
+
+How long the query waited for locks.
+
+
+--
+
+*`mysql.slowlog.innodb.queue_wait.sec`*::
++
+--
+type: long
+
+How long the query waited to enter the InnoDB queue and to be executed once in the queue.
+
+
+--
+
+*`mysql.slowlog.innodb.pages_distinct`*::
++
+--
+type: long
+
+Approximated count of pages accessed to execute the query.
+
+
 --
 
 *`mysql.slowlog.user`*::

diff --git a/filebeat/module/mysql/fields.go b/filebeat/module/mysql/fields.go
diff --git a/filebeat/module/mysql/slowlog/_meta/fields.yml b/filebeat/module/mysql/slowlog/_meta/fields.yml
@@ -24,6 +24,11 @@
       type: long
       description: >
         The number of rows modified by the query.
+    - name: bytes_sent
+      type: long
+      format: bytes
+      description: >
+        The size of the query result.
     - name: query
       description: >
         The slow query.
@@ -39,6 +44,14 @@
       type: keyword
       description: >
         Current authenticated user, used to determine access privileges. Can differ from the value for user.
+    - name: last_errno
+      type: keyword
+      description: >
+        Last SQL error seen.
+    - name: killed
+      type: keyword
+      description: >
+        Code of the reason if the query was killed.
 
     - name: query_cache_hit
       type: boolean
@@ -52,6 +65,19 @@
       type: boolean
       description: >
         Whether the query needed temporary tables on disk.
+    - name: tmp_tables
+      type: long
+      description: > 
+        Number of temporary tables created for this query
+    - name: tmp_disk_tables
+      type: long
+      description: >
+        Number of temporary tables created on disk for this query.
+    - name: tmp_table_sizes
+      type: long
+      format: bytes
+      description: 
+        Size of temporary tables created for this query.
     - name: filesort
       type: boolean
       description: >
@@ -76,6 +102,53 @@
       type: long
       description: >
         Number of merge passes executed for the query.
+    - name: log_slow_rate_type
+      type: keyword
+      description: >
+        Type of slow log rate limit, it can be `session` if the rate limit
+        is applied per session, or `query` if it applies per query.
+    - name: log_slow_rate_limit
+      type: keyword
+      description: >
+        Slow log rate limit, a value of 100 means that one in a hundred queries
+        or sessions are being logged.
+
+    # https://www.percona.com/doc/percona-server/5.7/diagnostics/slow_extended.html
+    - name: innodb
+      type: group
+      description: >
+        Contains fields relative to InnoDB engine
+      fields:
+        - name: trx_id
+          type: keyword
+          description: >
+            Transaction ID
+        - name: io_r_ops
+          type: long
+          description: >
+            Number of page read operations.
+        - name: io_r_bytes
+          type: long
+          format: bytes
+          description: >
+            Bytes read during page read operations.
+        - name: io_r_wait.sec
+          type: long
+          description: >
+            How long it took to read all needed data from storage.
+        - name: rec_lock_wait.sec
+          type: long
+          description: >
+            How long the query waited for locks.
+        - name: queue_wait.sec
+          type: long
+          description: >
+            How long the query waited to enter the InnoDB queue and to be executed once
+            in the queue.
+        - name: pages_distinct
+          type: long
+          description: >
+            Approximated count of pages accessed to execute the query.
 
     - name: user
       type: alias
@@ -89,3 +162,4 @@
       type: alias
       path: source.ip
       migration: true
+
diff --git a/filebeat/module/mysql/slowlog/ingest/pipeline.json b/filebeat/module/mysql/slowlog/ingest/pipeline.json
@@ -4,7 +4,7 @@
     "grok": {
       "field": "message",
       "patterns":[
-        "^# User@Host: %{USER:user.name}(\\[%{USER:mysql.slowlog.current_user}\\])? @ %{HOSTNAME:source.domain}? \\[%{IP:source.ip}?\\](\\s*Id:\\s* %{NUMBER:mysql.thread_id:long})?\n(# Thread_id:%{SPACE}%{NUMBER:mysql.thread_id}%{METRICSPACE}Schema: %{WORD:mysql.slowlog.schema}?%{METRICSPACE}QC_hit: %{WORD:mysql.slowlog.query_cache_hit}\n)?%{METRICSPACE}Query_time: %{NUMBER:mysql.slowlog.query_time.sec:float}%{METRICSPACE}Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec:float}%{METRICSPACE}Rows_sent: %{NUMBER:mysql.slowlog.rows_sent:long}%{METRICSPACE}Rows_examined: %{NUMBER:mysql.slowlog.rows_examined:long}%{METRICSPACE}(Rows_affected: %{NUMBER:mysql.slowlog.rows_affected:long}%{METRICSPACE})?(Full_scan: %{WORD:mysql.slowlog.full_scan}%{METRICSPACE})?(Full_join: %{WORD:mysql.slowlog.full_join}%{METRICSPACE})?(Tmp_table: %{WORD:mysql.slowlog.tmp_table}%{METRICSPACE})?(Tmp_table_on_disk: %{WORD:mysql.slowlog.tmp_table_on_disk}%{METRICSPACE})?(Filesort: %{WORD:mysql.slowlog.filesort}%{METRICSPACE})?(Filesort_on_disk: %{WORD:mysql.slowlog.filesort_on_disk}%{METRICSPACE})?(Merge_passes: %{NUMBER:mysql.slowlog.merge_passes}%{METRICSPACE})?(Priority_queue: %{WORD:mysql.slowlog.priority_queue}%{METRICSPACE})?%{EXPLAIN}?(use %{WORD:mysql.slowlog.schema};\n)?SET timestamp=%{NUMBER:mysql.slowlog.timestamp:long};\n%{GREEDYMULTILINE:mysql.slowlog.query}"
+        "^# User@Host: %{USER:user.name}(\\[%{USER:mysql.slowlog.current_user}\\])? @ %{HOSTNAME:source.domain}? \\[%{IP:source.ip}?\\]%{METRICSPACE}(Id:%{SPACE}%{NUMBER:mysql.thread_id:long}%{METRICSPACE})?(Thread_id:%{SPACE}%{NUMBER:mysql.thread_id}%{METRICSPACE})?(Schema:%{SPACE}%{WORD:mysql.slowlog.schema}?%{METRICSPACE})?(Last_errno: %{NUMBER:mysql.slowlog.last_errno:long}%{METRICSPACE})?(Killed: %{NUMBER:mysql.slowlog.killed:long}%{METRICSPACE})?(QC_hit: %{WORD:mysql.slowlog.query_cache_hit}%{METRICSPACE})?(Query_time: %{NUMBER:mysql.slowlog.query_time.sec:float}%{METRICSPACE})?(Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec:float}%{METRICSPACE})?(Rows_sent: %{NUMBER:mysql.slowlog.rows_sent:long}%{METRICSPACE})?(Rows_examined: %{NUMBER:mysql.slowlog.rows_examined:long}%{METRICSPACE})?(Rows_affected: %{NUMBER:mysql.slowlog.rows_affected:long}%{METRICSPACE})?(Bytes_sent: %{NUMBER:mysql.slowlog.bytes_sent:long}%{METRICSPACE})?(Tmp_tables: %{NUMBER:mysql.slowlog.tmp_tables:long}%{METRICSPACE})?(Tmp_disk_tables: %{NUMBER:mysql.slowlog.tmp_disk_tables}%{METRICSPACE})?(Tmp_table_sizes: %{NUMBER:mysql.slowlog.tmp_table_sizes:long}%{METRICSPACE})?(InnoDB_trx_id: %{WORD:mysql.slowlog.innodb.trx_id}%{METRICSPACE})?(QC_Hit: %{WORD:mysql.slowlog.query_cache_hit}%{METRICSPACE})?(Full_scan: %{WORD:mysql.slowlog.full_scan}%{METRICSPACE})?(Full_join: %{WORD:mysql.slowlog.full_join}%{METRICSPACE})?(Tmp_table: %{WORD:mysql.slowlog.tmp_table}%{METRICSPACE})?(Tmp_table_on_disk: %{WORD:mysql.slowlog.tmp_table_on_disk}%{METRICSPACE})?(Filesort: %{WORD:mysql.slowlog.filesort}%{METRICSPACE})?(Filesort_on_disk: %{WORD:mysql.slowlog.filesort_on_disk}%{METRICSPACE})?(Merge_passes: %{NUMBER:mysql.slowlog.merge_passes:long}%{METRICSPACE})?(Priority_queue: %{WORD:mysql.slowlog.priority_queue}%{METRICSPACE})?(No InnoDB statistics available for this query%{METRICSPACE})?(InnoDB_IO_r_ops: %{NUMBER:mysql.slowlog.innodb.io_r_ops:long}%{METRICSPACE})?(InnoDB_IO_r_bytes: %{NUMBER:mysql.slowlog.innodb.io_r_bytes:long}%{METRICSPACE})?(InnoDB_IO_r_wait: %{NUMBER:mysql.slowlog.innodb.io_r_wait.sec:float}%{METRICSPACE})?(InnoDB_rec_lock_wait: %{NUMBER:mysql.slowlog.innodb.rec_lock_wait.sec:float}%{METRICSPACE})?(InnoDB_queue_wait: %{NUMBER:mysql.slowlog.innodb.queue_wait.sec:float}%{METRICSPACE})?(InnoDB_pages_distinct: %{NUMBER:mysql.slowlog.innodb.pages_distinct:long}%{METRICSPACE})?(Log_slow_rate_type: %{WORD:mysql.slowlog.log_slow_rate_type}%{METRICSPACE})?(Log_slow_rate_limit: %{NUMBER:mysql.slowlog.log_slow_rate_limit:long}%{METRICSPACE})?%{EXPLAIN}?(use %{WORD:mysql.slowlog.schema};\n)?SET timestamp=%{NUMBER:mysql.slowlog.timestamp:long};\n%{GREEDYMULTILINE:mysql.slowlog.query}"
         ],
       "pattern_definitions" : {
         "GREEDYMULTILINE": "(.|\n)*",
@@ -56,13 +56,6 @@
       "field": "mysql.slowlog.timestamp",
       "ignore_missing": true
     }
-  }, {
-    "gsub": {
-      "field": "mysql.slowlog.query",
-       "pattern": "\n# Time: [0-9]+ [0-9][0-9]:[0-9][0-9]:[0-9][0-9](\\.[0-9]+)?$",
-       "replacement": "",
-       "ignore_failure": true
-    }
   }],
   "on_failure" : [{
     "set" : {

diff --git a/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log-expected.json b/filebeat/module/mysql/slowlog/test/mariadb-10.2.12.log-expected.json
@@ -42,7 +42,7 @@
         "mysql.slowlog.full_join": false,
         "mysql.slowlog.full_scan": true,
         "mysql.slowlog.lock_time.sec": 0.0,
-        "mysql.slowlog.merge_passes": "0",
+        "mysql.slowlog.merge_passes": 0,
         "mysql.slowlog.priority_queue": false,
         "mysql.slowlog.query": "call PROC('blah');",
         "mysql.slowlog.query_cache_hit": false,

diff --git a/filebeat/module/mysql/slowlog/test/percona-ubuntu-5.7.19-innodb.log b/filebeat/module/mysql/slowlog/test/percona-ubuntu-5.7.19-innodb.log
@@ -0,0 +1,36 @@
+# Time: 2019-01-21T06:36:03.868128Z
+# User@Host: exporter[exporter] @ localhost []  Id: 14367293
+# Schema:   Last_errno: 1370  Killed: 0
+# Query_time: 0.050365  Lock_time: 0.010733  Rows_sent: 16  Rows_examined: 3146  Rows_affected: 0
+# Bytes_sent: 1362  Tmp_tables: 376  Tmp_disk_tables: 71  Tmp_table_sizes: 606208
+# QC_Hit: No  Full_scan: Yes  Full_join: Yes  Tmp_table: Yes  Tmp_table_on_disk: Yes
+# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
+# No InnoDB statistics available for this query
+# Log_slow_rate_type: query  Log_slow_rate_limit: 100
+SET timestamp=1548052563;
+SELECT t.table_schema, t.table_name, column_name, `auto_increment`,
+                  pow(2, case data_type
+                    when 'tinyint'   then 7
+                    when 'smallint'  then 15
+                    when 'mediumint' then 23
+                    when 'int'       then 31
+                    when 'bigint'    then 63
+                    end+(column_type like '% unsigned'))-1 as max_int
+                  FROM information_schema.tables t
+                  JOIN information_schema.columns c
+                    ON BINARY t.table_schema = c.table_schema AND BINARY t.table_name = c.table_name
+                  WHERE c.extra = 'auto_increment' AND t.auto_increment IS NOT NULL;
+# Time: 2019-01-21T09:15:36.487710Z
+# User@Host: test[test] @  [192.168.123.123]  Id: 14370752
+# Schema: test  Last_errno: 3170  Killed: 0
+# Query_time: 153.883481  Lock_time: 0.024022  Rows_sent: 0  Rows_examined: 120309968  Rows_affected: 19198
+# Bytes_sent: 62  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
+# InnoDB_trx_id: 69BB9C7F9
+# QC_Hit: No  Full_scan: No  Full_join: No  Tmp_table: No  Tmp_table_on_disk: No
+# Filesort: No  Filesort_on_disk: No  Merge_passes: 0
+#   InnoDB_IO_r_ops: 9744  InnoDB_IO_r_bytes: 79822848  InnoDB_IO_r_wait: 0.883446
+#   InnoDB_rec_lock_wait: 0.003038  InnoDB_queue_wait: 0.000000
+#   InnoDB_pages_distinct: 64872
+# Log_slow_rate_type: query  Log_slow_rate_limit: 100
+SET timestamp=1548062136;
+UPDATE test    SET test.state = 'NOT_RELEVANT', modified = now()  WHERE test.id IN (26328833, 390, 149386, 152268, 160997, 165304, 168524, 184105, 193022, 194533, 194862, 196469, 196487, 246398, 256594, 260566, 261862, 262342, 263701, 264166, 264607, 267671, 274879, 276704, 280964, 284366, 289323, 289843, 290004, 298999, 301213, 303494, 307920, 311905, 316311, 318404, 330846, 340751, 341433, 357191, 369184, 376876, 378360, 378492, 379470, 382131, 384077, 388368, 396815, 396881, 398272, 398950, 399589, 401299, 408787, 411293, 419109, 425953, 427659, 433183, 437030, 438332, 438386, 447037, 454231, 455257, 455344, 456385, 460420, 460425, 461252, 462338, 462531, 462684, 463104, 463395, 471073, 480069, 480078, 482399, 485205, 487971, 497191, 500261, 501855, 517585, 519310, 519654, 522575, 538425, 543560, 562315, 573934, 583466, 583490, 583502, 597605, 600875, 601546, 603879, 604467, 604619, 757786, 797285, 799155, 802905, 806268, 806798, 811974, 819684, 822629, 826406, 837733, 840128, 840131, 840251, 840277, 840302, 842966, 844294, 844300, 847837, 852503, 854272, 854299, 862983, 881405, 881461, 881467, 881560, 881908, 882435, 882453, 882651, 882711, 882811, 888265, 888286, 914091, 916288, 916316, 917708, 918238, 918887, 919222, 926607, 976977, 977010, 977067, 977131, 977185, 988249, 988276, 988336, 988360, 988504, 990994);