Mysql-Module Percona Support

[strowi]

Hi,

As requested: https://discuss.elastic.co/t/mysql-module-grok-parsing-error/125561

trying to get percona slow-logs into es with the mysql-module. But it seems there is some pattern mismatch?

• Version: 6.2.3

• Operating System: Ubuntu 16.04.3 LTS

• Steps to Reproduce:

filebeat.prospectors:

filebeat.config.modules:
  # Glob pattern for configuration loading
  path: ${path.config}/modules.d/*.yml

  # Set to true to enable config reloading
  reload.enabled: false

  # Period on which files under path should be checked for changes
  #reload.period: 10s

output.elasticsearch:
  hosts: ["es:30092"]
  index: "percona-%{[beat.version]}-%{+yyyy.MM.dd}"

setup:
  template:
    name: "percona-%{[beat.version]}"
    pattern: "percona-%{[beat.version]}-*"

filebeat.modules:
 - module: mysql
   # Error logs
   error:
     enabled: true
     var.paths: [/var/log/mysql/error.log]
   # Slow logs
   slowlog:
     enabled: true
     var.paths: [/var/log/mysql/mysql-slow.log]

error:

||Provided Grok expressions do not match field value: [# Time: 2018-03-26T08:03:59.598547Z]|

message:

@timestamp:
    March 26th 2018, 10:04:06.883
offset:
    6,594
beat.hostname:
    db03
beat.name:
    db03
beat.version:
    6.2.3
prospector.type:
    log
source:
    /var/log/mysql/mysql-slow.log
fileset.module:
    mysql
fileset.name:
    slowlog
fields.env:
    prod2
message:
    # User@Host: root[root] @ localhost [] Id: 37045034 # Schema: Last_errno: 0 Killed: 0 # Query_time: 10.000204 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0 # Bytes_sent: 57 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0 # 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 # No InnoDB statistics available for this query # Log_slow_rate_type: session Log_slow_rate_limit: 100 SET timestamp=1522051439; select sleep(10);
error.message:
    Provided Grok expressions do not match field value: [# User@Host: root[root] @ localhost [] Id: 37045034\n# Schema: Last_errno: 0 Killed: 0\n# Query_time: 10.000204 Lock_time: 0.000000 Rows_sent: 1 Rows_examined: 0 Rows_affected: 0\n# Bytes_sent: 57 Tmp_tables: 0 Tmp_disk_tables: 0 Tmp_table_sizes: 0\n# QC_Hit: No Full_scan: No Full_join: No Tmp_table: No Tmp_table_on_disk: No\n# Filesort: No Filesort_on_disk: No Merge_passes: 0\n# No InnoDB statistics available for this query\n# Log_slow_rate_type: session Log_slow_rate_limit: 100\nSET timestamp=1522051439;\nselect sleep(10);]
_id:
    Uv9WYWIBCQzjQvHMD8TZ
_type:
    doc
_index:
    percona-6.2.3-2018.03.26
_score:
    - 

original log:

# Time: 2018-03-26T08:03:59.598547Z
# User@Host: root[root] @ localhost []  Id: 37045034
# Schema:   Last_errno: 0  Killed: 0
# Query_time: 10.000204  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 57  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# 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
# No InnoDB statistics available for this query
# Log_slow_rate_type: session  Log_slow_rate_limit: 100
SET timestamp=1522051439;
select sleep(10);

regards,
strowi

[Fanduzi]

Same problem

Suggest Mysql-Module compatible Official, Percona and Mariadb versions

[asrob]

Any updates?

[strowi]

Sad to say my grok is not fit enough... will have to dig deeper into this.. Or has anyone found a way to at least ignore the problematic lines?

[dkanchev]

@vadimtk @puneet0191 @delgod Can you guys provide more information about what are the exact differences between the Percona slow logs and the MySQL slow logs. I may have some time to fix the grok filters that beats uses. It will be even better if you already have fixed this for some of your Percona users. Thanks in advance for the info!

[strowi]

Percona 5.7.19

 zcat /var/log/mysql/mysql-slow.log.7.gz 
/usr/sbin/mysqld, Version: 5.7.19-17-57-log (Percona XtraDB Cluster (GPL), Release rel17, Revision 35cdc81, WSREP version 29.22, wsrep_29.22). started with:
Tcp port: 3306  Unix socket: /var/run/mysqld/mysqld.sock
Time                 Id Command    Argument
# Time: 2018-09-21T09:10:32.614283Z
# User@Host: root[root] @ localhost []  Id: 718391
# Schema:   Last_errno: 0  Killed: 0
# Query_time: 10.000281  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0  Rows_affected: 0
# Bytes_sent: 57  Tmp_tables: 0  Tmp_disk_tables: 0  Tmp_table_sizes: 0
# 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
# No InnoDB statistics available for this query
# Log_slow_rate_type: session  Log_slow_rate_limit: 100
SET timestamp=1537521032;
select sleep(10);

[delgod]

@dkanchev, please check the following docs, each doc has "Changes to the Log Format" section:
https://www.percona.com/doc/percona-server/5.5/diagnostics/slow_extended_55.html
https://www.percona.com/doc/percona-server/5.6/diagnostics/slow_extended.html
https://www.percona.com/doc/percona-server/5.7/diagnostics/slow_extended.html

[HagK]

i can now provide a well tested GROK pattern for some configurations and usage of percona slowlogs
i use this as the 3rd pattern in my "Pipeline for parsing MySQL slow logs." - my 2nd for MariaDB is not well evaluated yet
"^# User@Host: %{USER:mysql.slowlog.user}(\\[[^\\]]+\\])? @ (%{HOSTNAME:mysql.slowlog.host})? \\[(%{IP:mysql.slowlog.ip})?\\](\\s*Id:\\s* %{NUMBER:mysql.slowlog.id})?\n# Schema:\\s* (%{WORD:mysql.slowlog.schema}\\s*)? Last_errno:\\s* %{NUMBER:mysql.slowlog.last_errno}\\s* Killed: %{NUMBER:mysql.slowlog.killed}\n# Query_time: %{NUMBER:mysql.slowlog.query_time.sec}\\s* Lock_time: %{NUMBER:mysql.slowlog.lock_time.sec}\\s* Rows_sent: %{NUMBER:mysql.slowlog.rows_sent}\\s* Rows_examined: %{NUMBER:mysql.slowlog.rows_examined}\\s* Rows_affected: %{NUMBER:mysql.slowlog.rows_affected}\n# Bytes_sent: %{NUMBER:mysql.slowlog.bytes_send}\\s* Tmp_tables: %{NUMBER:mysql.slowlog.tmp_tables}\\s* Tmp_disk_tables: %{NUMBER:mysql.slowlog.tmp_disk_tables}\\s* Tmp_table_sizes: %{NUMBER:mysql.slowlog.tmp_table_size}\n(# InnoDB_trx_id: %{WORD:mysql.slowlog.innodb_trx_id}\n)?(# Profile_starting: .*\n)?(# Profile_total: %{NUMBER:mysql.slowlog.profile_total} Profile_total_cpu: %{NUMBER:mysql.slowlog.profile_total_cpu}\n)?# QC_Hit: %{WORD:mysql.slowlog.qc_hit}\\s* Full_scan: %{WORD:mysql.slowlog.full_scan}\\s* Full_join: %{WORD:mysql.slowlog.full_join}\\s* Tmp_table: %{WORD:mysql.slowlog.tmp_table}\\s* Tmp_table_on_disk: %{WORD:mysql.slowlog.tmp_table_on_disk}\n# Filesort: %{WORD:mysql.slowlog.filesort}\\s* Filesort_on_disk: %{WORD:mysql.slowlog.filesort_on_disk}\\s* Merge_passes: %{NUMBER:mysql.slowlog.merge_passes}\n(# No InnoDB statistics available for this query\n)?(#\\s* InnoDB_IO_r_ops: %{NUMBER:mysql.slowlog.innodb_r_ops}\\s* InnoDB_IO_r_bytes: %{NUMBER:mysql.slowlog.innodb_r_bytes}\\s* InnoDB_IO_r_wait: %{NUMBER:mysql.slowlog.innodb_r_wait.sec}\n)?(#\\s* InnoDB_rec_lock_wait: %{NUMBER:mysql.slowlog.innodb_rec_lock_wait.sec}\\s* InnoDB_queue_wait: %{NUMBER:mysql.slowlog.innodb_queue_wait.sec}\n)?(#\\s* InnoDB_pages_distinct: %{NUMBER:mysql.slowlog.pages_distinct}\n)?(# Log_slow_rate_type: %{WORD:mysql.slowlog.slow_rate_type}\\s* Log_slow_rate_limit: %{NUMBER:mysql.slowlog.slow_rate_limit}\n)?(use %{WORD:mysql.slowlog.use};\n)?(SET timestamp=%{NUMBER:mysql.slowlog.timestamp};\n)?%{GREEDYMULTILINE:mysql.slowlog.query}"

[jsoriano]

@HagK wow, thanks! I am finishing a PR to support mariadb (#9731) and I was thinking on trying with Percona later. Your patterns can be really valuable, specially as they also include the innodb metrics 🙂

Would you like to open a PR with your patterns and some example files for percona after #9731 gets merged?

[HagK]

sure, i can collect some different log configuration examples for percona and create a pull request.

btw, your mariadb pattern doesnt support https://mariadb.com/kb/en/library/explain-in-the-slow-query-log/
?
and is the line (# Thread_id...)? sometimes optional? i could not reproduce this. The schema in this line could be empty, but the thread-id is always logged for me.

[jsoriano]

sure, i can collect some different log configuration examples for percona and create a pull request.

Thanks

btw, your mariadb pattern doesnt support https://mariadb.com/kb/en/library/explain-in-the-slow-query-log/
?

Right, this is not supported yet, we can also add it later, as well as support for the innodb entries. Does your pattern support it?

and is the line (# Thread_id...)? sometimes optional? i could not reproduce this. The schema in this line could be empty, but the thread-id is always logged for me.

Older mysql versions don't log the thread id, or do it as Id:..., all these options are supported.

[jsoriano]

@HagK #9731 merged, I added at the end a pattern to ignore the "explain" part by now, so logs are still parsed.

[HagK]

the pull request is commited but conflicts, because a have commited your modification too :(

percona doesnt support the explain lines, so i must not think about a support

[jsoriano]

the pull request is commited but conflicts, because a have commited your modification too :(

Oh, thanks for the PR, I'll take a look.

percona doesnt support the explain lines, so i must not think about a support

I left these lines as optional, so the module works in any case. They are still not parsed, if they are included they are just ignored by filebeat.