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.

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

Add support to MySQL 8 extra fields in slow log #11417

Merged
merged 6 commits into from
Mar 25, 2019
Merged
Show file tree
Hide file tree
Changes from all commits
Commits
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
1 change: 1 addition & 0 deletions CHANGELOG.next.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -306,6 +306,7 @@ https://github.com/elastic/beats/compare/v7.0.0-alpha2...master[Check the HEAD d
- Add the `network.community_id` flow identifier to field to the IPTables, Suricata, and Zeek modules. {pull}11005[11005]
- Add support for loading custom NetFlow and IPFIX field definitions to netflow input. {pull}10945[10945]
- Added categorization fields for SSH login events in the system/auth fileset. {pull}11334[11334]
- Add support for MySQL 8.0 slow logs and tests also for Percona 8.0 and MariaDB 10.3. {pull}11417[11417]

*Heartbeat*

Expand Down
124 changes: 123 additions & 1 deletion filebeat/docs/fields.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -7273,7 +7273,19 @@ type: long

format: bytes

The size of the query result.
The number of bytes sent to client.


--

*`mysql.slowlog.bytes_received`*::
+
--
type: long

format: bytes

The number of bytes received from client.


--
Expand Down Expand Up @@ -7454,6 +7466,46 @@ type: long
Number of merge passes executed for the query.


--

*`mysql.slowlog.sort_merge_passes`*::
+
--
type: long

Number of merge passes that the sort algorithm has had to do.


--

*`mysql.slowlog.sort_range_count`*::
+
--
type: long

Number of sorts that were done using ranges.


--

*`mysql.slowlog.sort_rows`*::
+
--
type: long

Number of sorted rows.


--

*`mysql.slowlog.sort_scan_count`*::
+
--
type: long

Number of sorts that were done by scanning the table.


--

*`mysql.slowlog.log_slow_rate_type`*::
Expand All @@ -7474,6 +7526,76 @@ type: keyword
Slow log rate limit, a value of 100 means that one in a hundred queries or sessions are being logged.


--

*`mysql.slowlog.read_first`*::
+
--
type: long

The number of times the first entry in an index was read.


--

*`mysql.slowlog.read_last`*::
+
--
type: long

The number of times the last key in an index was read.


--

*`mysql.slowlog.read_key`*::
+
--
type: long

The number of requests to read a row based on a key.


--

*`mysql.slowlog.read_next`*::
+
--
type: long

The number of requests to read the next row in key order.


--

*`mysql.slowlog.read_prev`*::
+
--
type: long

The number of requests to read the previous row in key order.


--

*`mysql.slowlog.read_rnd`*::
+
--
type: long

The number of requests to read a row based on a fixed position.


--

*`mysql.slowlog.read_rnd_next`*::
+
--
type: long

The number of requests to read the next row in the data file.


--

[float]
Expand Down
4 changes: 2 additions & 2 deletions filebeat/docs/modules/mysql.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -16,8 +16,8 @@ include::../include/what-happens.asciidoc[]
[float]
=== Compatibility

The +{modulename}+ module was tested with logs from MySQL 5.5 and 5.7,
MariaDB 10.1 and 10.2, and Percona 5.7.
The +{modulename}+ module was tested with logs from MySQL 5.5, 5.7 and 8.0,
MariaDB 10.1, 10.2 and 10.3, and Percona 5.7 and 8.0.

On Windows, the module was tested with MySQL installed from the Chocolatey
repository.
Expand Down
4 changes: 2 additions & 2 deletions filebeat/module/mysql/_meta/docs.asciidoc
Original file line number Diff line number Diff line change
Expand Up @@ -11,8 +11,8 @@ include::../include/what-happens.asciidoc[]
[float]
=== Compatibility

The +{modulename}+ module was tested with logs from MySQL 5.5 and 5.7,
MariaDB 10.1 and 10.2, and Percona 5.7.
The +{modulename}+ module was tested with logs from MySQL 5.5, 5.7 and 8.0,
MariaDB 10.1, 10.2 and 10.3, and Percona 5.7 and 8.0.

On Windows, the module was tested with MySQL installed from the Chocolatey
repository.
Expand Down
12 changes: 12 additions & 0 deletions filebeat/module/mysql/error/test/mysql-ubuntu-8.0.15.log
Original file line number Diff line number Diff line change
@@ -0,0 +1,12 @@
2019-03-24T13:44:25.484123Z 0 [System] [MY-013169] [Server] /usr/sbin/mysqld (mysqld 8.0.15) initializing of server in progress as process 1640
2019-03-24T13:44:27.924508Z 5 [Warning] [MY-010453] [Server] root@localhost is created with an empty password ! Please consider switching off the --initialize-insecure option.
2019-03-24T13:44:29.065309Z 0 [System] [MY-013170] [Server] /usr/sbin/mysqld (mysqld 8.0.15) initializing of server has completed
2019-03-24T13:44:31.085670Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.15) starting as process 1688
2019-03-24T13:44:31.533096Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2019-03-24T13:44:31.534587Z 0 [Warning] [MY-011810] [Server] Insecure configuration for --pid-file: Location '/tmp' in the path is accessible to all OS users. Consider choosing a different directory.
2019-03-24T13:44:31.555406Z 6 [System] [MY-013172] [Server] Received SHUTDOWN from user boot. Shutting down mysqld (Version: 8.0.15).
2019-03-24T13:44:33.236624Z 0 [System] [MY-010910] [Server] /usr/sbin/mysqld: Shutdown complete (mysqld 8.0.15) MySQL Community Server - GPL.
2019-03-24T13:44:34.072713Z 0 [System] [MY-010116] [Server] /usr/sbin/mysqld (mysqld 8.0.15) starting as process 1834
2019-03-24T13:44:34.406962Z 0 [Warning] [MY-010068] [Server] CA certificate ca.pem is self signed.
2019-03-24T13:44:34.420123Z 0 [System] [MY-010931] [Server] /usr/sbin/mysqld: ready for connections. Version: '8.0.15' socket: '/var/run/mysqld/mysqld.sock' port: 3306 MySQL Community Server - GPL.
2019-03-24T13:44:34.572158Z 0 [System] [MY-011323] [Server] X Plugin ready for connections. Socket: '/var/run/mysqld/mysqlx.sock' bind-address: '::' port: 33060
2 changes: 1 addition & 1 deletion filebeat/module/mysql/fields.go

Some generated files are not rendered by default. Learn more about how customized files appear on GitHub.

51 changes: 50 additions & 1 deletion filebeat/module/mysql/slowlog/_meta/fields.yml
Original file line number Diff line number Diff line change
Expand Up @@ -24,7 +24,12 @@
type: long
format: bytes
description: >
The size of the query result.
The number of bytes sent to client.
- name: bytes_received
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

received.bytes?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Same here, plus having already bytes_sent.

type: long
format: bytes
description: >
The number of bytes received from client.
- name: query
description: >
The slow query.
Expand Down Expand Up @@ -98,6 +103,22 @@
type: long
description: >
Number of merge passes executed for the query.
- name: sort_merge_passes
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

sort.* etc?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Also here I'd keep original names, they are very specific names.

type: long
description: >
Number of merge passes that the sort algorithm has had to do.
- name: sort_range_count
type: long
description: >
Number of sorts that were done using ranges.
- name: sort_rows
type: long
description: >
Number of sorted rows.
- name: sort_scan_count
type: long
description: >
Number of sorts that were done by scanning the table.
- name: log_slow_rate_type
type: keyword
description: >
Expand All @@ -108,6 +129,34 @@
description: >
Slow log rate limit, a value of 100 means that one in a hundred queries
or sessions are being logged.
- name: read_first
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Should we make this read.first etc?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This module is keeping the names of the original fields, I'd continue using these values.

type: long
description: >
The number of times the first entry in an index was read.
- name: read_last
type: long
description: >
The number of times the last key in an index was read.
- name: read_key
type: long
description: >
The number of requests to read a row based on a key.
- name: read_next
type: long
description: >
The number of requests to read the next row in key order.
- name: read_prev
type: long
description: >
The number of requests to read the previous row in key order.
- name: read_rnd
type: long
description: >
The number of requests to read a row based on a fixed position.
- name: read_rnd_next
type: long
description: >
The number of requests to read the next row in the data file.

# https://www.percona.com/doc/percona-server/5.7/diagnostics/slow_extended.html
- name: innodb
Expand Down
2 changes: 1 addition & 1 deletion filebeat/module/mysql/slowlog/ingest/pipeline.json
Original file line number Diff line number Diff line change
Expand Up @@ -4,7 +4,7 @@
"grok": {
"field": "message",
"patterns":[
"^# 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:temp.duration: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}"
"^# 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:temp.duration: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})?(Thread_id: %{NUMBER:mysql.thread_id}%{METRICSPACE})?(Errno: %{NUMBER:mysql.slowlog.last_errno:long}%{METRICSPACE})?(Killed: %{NUMBER:mysql.slowlog.killed:long}%{METRICSPACE})?(Bytes_received: %{NUMBER:mysql.slowlog.bytes_received:long}%{METRICSPACE})?(Bytes_sent: %{NUMBER:mysql.slowlog.bytes_sent:long}%{METRICSPACE})?(Read_first: %{NUMBER:mysql.slowlog.read_first:long}%{METRICSPACE})?(Read_last: %{NUMBER:mysql.slowlog.read_last:long}%{METRICSPACE})?(Read_key: %{NUMBER:mysql.slowlog.read_key:long}%{METRICSPACE})?(Read_next: %{NUMBER:mysql.slowlog.read_next:long}%{METRICSPACE})?(Read_prev: %{NUMBER:mysql.slowlog.read_prev:long}%{METRICSPACE})?(Read_rnd: %{NUMBER:mysql.slowlog.read_rnd:long}%{METRICSPACE})?(Read_rnd_next: %{NUMBER:mysql.slowlog.read_rnd_next:long}%{METRICSPACE})?(Sort_merge_passes: %{NUMBER:mysql.slowlog.sort_merge_passes:long}%{METRICSPACE})?(Sort_range_count: %{NUMBER:mysql.slowlog.sort_range_count:long}%{METRICSPACE})?(Sort_rows: %{NUMBER:mysql.slowlog.sort_rows:long}%{METRICSPACE})?(Sort_scan_count: %{NUMBER:mysql.slowlog.sort_scan_count:long}%{METRICSPACE})?(Created_tmp_disk_tables: %{NUMBER:mysql.slowlog.tmp_disk_tables:long}%{METRICSPACE})?(Created_tmp_tables: %{NUMBER:mysql.slowlog.tmp_tables: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})?(Start: %{TIMESTAMP_ISO8601:event.start}%{METRICSPACE})?(End: %{TIMESTAMP_ISO8601:event.end}%{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}"
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

That is a big one :-) I wonder if in the future we could split this up in multiple patterns to make it more readable / reviewable.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yes, this is quite a monster and painful to modify, not sure what alternatives we have, even with patterns this would be quite ugly.
I think we should parse this with code, not sure if in filebeat side (a processor?) or in painless in the pipeline.

],
"pattern_definitions" : {
"GREEDYMULTILINE": "(.|\n)*",
Expand Down
18 changes: 18 additions & 0 deletions filebeat/module/mysql/slowlog/test/mariadb-10.3.13.log
Original file line number Diff line number Diff line change
@@ -0,0 +1,18 @@
/usr/sbin/mysqld, Version: 10.3.13-MariaDB-1:10.3.13+maria~bionic-log (mariadb.org binary distribution). started with:
Tcp port: 3306 Unix socket: /var/run/mysqld/mysqld.sock
Time Id Command Argument
# Time: 190324 16:03:00
# User@Host: root[root] @ localhost []
# Thread_id: 37 Schema: employees QC_hit: No
# Query_time: 2.461578 Lock_time: 0.000196 Rows_sent: 10 Rows_examined: 3145718
# Rows_affected: 0 Bytes_sent: 319
# Tmp_tables: 1 Tmp_disk_tables: 0 Tmp_table_sizes: 4026528
# Full_scan: Yes Full_join: No Tmp_table: Yes Tmp_table_on_disk: No
# Filesort: Yes Filesort_on_disk: No Merge_passes: 0 Priority_queue: Yes
use employees;
SET timestamp=1553443380;
Copy link
Member

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Would be great to normally have at least 2 log entries to make sure the multiline works as expected.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think we are covered here, there are several test files, all of them are multiline and most of them generate more than 1 event.

SELECT last_name, MAX(salary) AS salary FROM employees
INNER JOIN salaries ON employees.emp_no = salaries.emp_no
GROUP BY last_name
ORDER BY salary DESC
LIMIT 10;
Loading