Elk building MySQL Slow log collection platform

The article "Small and medium-sized team quickly build SQL Automatic Audit system" We completed the automatic audit and implementation of SQL, not only improve the efficiency is also by the colleague's affirmation, the heart flattered. But the collection and processing of slow queries also cost us too much time and effort, how can we improve efficiency in this piece? and see how this article explains how to use elk to do slow log collection

Elk Introduction

Elk is the earliest Elasticsearch (hereinafter referred to as ES), Logstash, Kibana three open source software abbreviation, three software was later acquired by the same company, and added Xpark, beats and other components, renamed Elastic Stack, Become the most popular open source log solution Now, despite the new name but people still like to call her elk, now refers to the elk is based on these open-source software built log system.

Our program for collecting MySQL slow logs is as follows:

• MySQL Server installation filebeat as Agent collection Slowlog
• Filebeat read MySQL Slow log file to do simple filtering to Kafka cluster
• Logstash reads the Kafka cluster data and splits it into JSON format into the ES cluster after splitting by field
• Kibana read ES cluster data on a Web page

Slow Log classification

Currently the main use of the MySQL version has 5.5, 5.6 and 5.7, after careful comparison found that each version of the slow query log are slightly different, as follows:

5.5 Version Slow query log

# Time: 180810 8:45:12
# User @ Host: select [select] @ [10.63.253.59]
# Query_time: 1.064555 Lock_time: 0.000054 Rows_sent: 1 Rows_examined: 319707
SET timestamp = 1533861912;
SELECT COUNT (*) FROM hs_forum_thread t WHERE t.`fid` = '50 'AND t.`displayorder`> =' 0 ';
5.6 version slow query log

# Time: 160928 18:36:08
# User @ Host: root [root] @ localhost [] Id: 4922
# Query_time: 5.207662 Lock_time: 0.000085 Rows_sent: 1 Rows_examined: 526068
use db_name;
SET timestamp = 1475058968;
select count (*) from redeem_item_consume where id <= 526083;
5.7 version slow query log

# Time: 2018-07-09T10: 04: 14.666231Z
# User @ Host: bbs_code [bbs_code] @ [10.82.9.220] Id: 9304381
# Query_time: 5.274805 Lock_time: 0.000052 Rows_sent: 0 Rows_examined: 2
SET timestamp = 1531130654;
SELECT * FROM pre_common_session WHERE sid = 'Ba1cSC' OR lastactivity <1531129749;
Similarities and differences of slow query logs:

The format of the Time field is different for each version
Compared with version 5.6 and 5.7, version 5.5 has fewer Id fields
use db statement is not available for every slow log
There may be situations like the following, the slow query block # Time: multiple slow query statements may follow
# Time: 160918 2:00:03
# User @ Host: dba_monitor [dba_monitor] @ [10.63.144.82] Id: 968
# Query_time: 0.007479 Lock_time: 0.000181 Rows_sent: 172 Rows_examined: 344
SET timestamp = 1474135203;
SELECT table_schema as 'DB', table_name as 'TABLE', CONCAT (ROUND ((data_length + index_length) / (1024 * 1024 * 1024), 2), '') as 'TOTAL', TABLE_COMMENT FROM information_schema.TABLES ORDER BY data_length + index_length DESC;
# User @ Host: dba_monitor [dba_monitor] @ [10.63.144.82] Id: 969
# Query_time: 0.003303 Lock_time: 0.000395 Rows_sent: 233 Rows_examined: 233
SET timestamp = 1474135203;
select TABLE_SCHEMA, TABLE_NAME, COLUMN_NAME, ORDINAL_POSITION, COLUMN_TYPE, ifnull (COLUMN_COMMENT, 0) from COLUMNS where table_schema not in ('mysql', 'information_schema', 'performance_schema', 'test');
Processing ideas
Above we have analyzed the composition of the slow query statements of each version. Next, we will start collecting these data. How should we collect them?

Assemble log lines: MySQL's slow query log consists of multiple lines to form a complete log. When collecting logs, these lines must be assembled into a log for transmission and storage.
Time line processing: # Time: The beginning line may not exist, and we can determine the SQL execution time by the value of SET timestamp, so choose to filter and discard the Time line
A complete log: finally merge the lines starting with # User @ Host: and the lines ending with the SQL statement into a complete slow log statement
Determine the DB corresponding to SQL: not all slow log SQL exists in the line use db, so you cannot use this to determine the DB corresponding to SQL. There are no fields in the slow log to record the DB. Therefore, it is recommended to add db name when creating an account for the DB. Identification, for example, our account name is: projectName_dbName, so you can see which DB is the account name.
Determine the host corresponding to the SQL: I want to know which database server this SQL corresponds to through the log? There is also no field record host in the slow log, which can be solved by filebeat injection field. For example, we set the name field of filebeat to the server IP, so that the host corresponding to SQL can be determined through the field beat.name.
Filebeat configuration
The complete filebeat configuration file is as follows:

filebeat.prospectors:

-input_type: log
  paths:
    -/home/opt/data/slow/mysql_slow.log

  exclude_lines: ['^ \ # Time']
  
  multiline.pattern: '^ \ # Time | ^ \ # User'
  multiline.negate: true
  multiline.match: after
  
  tail_files: true

name: 10.82.9.89

output.kafka:
  hosts: ["10.82.9.202:9092","10.82.9.203:9092","10.82.9.204:9092"]
  topic: mysql_slowlog_v2
Explanation of important parameters:
input_type: specifies the type of input is log or stdin
paths: slow log paths, support regular such as /data/*.log
exclude_lines: filter out lines starting with # Time
multiline.pattern: Specify a regular expression when matching multiple lines, here matching lines starting with # Time or # User, Time lines must be matched before filtering
multiline.negate: defines whether the lines matched by the pattern above are used for multi-line merge, that is, whether it is defined as part of the log
multiline.match: defines how to combine skin rankings into time, before or after
tail_files: defines whether to read the log from the beginning or end of the file, defined here as true, collected from now on, regardless of the existing ones
name: Set the name of filebeat. If it is empty, it is the host name of the server. Here we define the server IP.
output.kafka: configure the Kafka cluster address and topic name to receive logs
Kafka received log format:
{"@timestamp": "2018-08-07T09: 36: 00.140Z", "beat": {"hostname": "db-7eb166d3", "name": "10.63.144.71", "version": "5.4 .0 "}," input_type ":" log "," message ":" # User @ Host: select [select] @ [10.63.144.16] Id: 23460596 \ n # Query_time: 0.155956 Lock_time: 0.000079 Rows_sent: 112 Rows_examined: 366458 \ nSET timestamp = 1533634557; \ nSELECT DISTINCT (uid) FROM common_member WHERE hideforum = -1 AND uid! = 0; "," offset ": 1753219021," source ":" / data / slow / mysql_slow.log "," type ":" log "}
Logstash configuration
The complete configuration file of logstash is as follows:

input {
    kafka {
        bootstrap_servers => "10.82.9.202:9092,10.82.9.203:9092,10.82.9.204:9092"
        topics => ["mysql_slowlog_v2"]
    }
}

filter {
    json {
        source => "message"
    }

    grok {
        # Have ID have use
        match => ["message", "(? m) ^ # User @ Host:% {USER: user} \ [[^ \]] + \] @ (?: (? <clienthost> \ S *))? \ [(?:% {IP: clientip})? \] \ S + Id: \ s% {NUMBER: id: int} \ n # Query_time:% {NUMBER: query_time: float} \ s + Lock_time:% { NUMBER: lock_time: float} \ s + Rows_sent:% {NUMBER: rows_sent: int} \ s + Rows_examined:% (NUMBER: rows_examined: int) \ nuse \ s (? <Dbname> \ w +); \ nSET \ s + timestamp =% {NUMBER: timestamp_mysql: int}; \ n (? <query>. *) "]

        # With ID without use
        match => ["message", "(? m) ^ # User @ Host:% {USER: user} \ [[^ \]] + \] @ (?: (? <clienthost> \ S *))? \ [(?:% {IP: clientip})? \] \ S + Id: \ s% {NUMBER: id: int} \ n # Query_time:% {NUMBER: query_time: float} \ s + Lock_time:% { NUMBER: lock_time: float} \ s + Rows_sent:% {NUMBER: rows_sent: int} \ s + Rows_examined:% {NUMBER: rows_examined: int} \ nSET \ s + timestamp =% {NUMBER: timestamp_mysql: int}; \ n (? <query>. *) "]

        # No ID has use
        match => ["message", "(? m) ^ # User @ Host:% {USER: user} \ [[^ \]] + \] @ (?: (? <clienthost> \ S *))? \ [(?:% {IP: clientip})? \] \ N # Query_time:% {NUMBER: query_time: float} \ s + Lock_time:% {NUMBER: lock_time: float} \ s + Rows_sent:% {NUMBER: rows_sent: int} \ s + Rows_examined:% {NUMBER: rows_examined: int} \ nuse \ s (? <dbname> \ w +); \ nSET \ s + timestamp =% {NUMBER: timestamp_mysql: int}; \ n (? <query>. *) "]

        # No ID without use
        match => ["message "," (? m) ^ # User @ Host:% {USER: user} \ [[^ \]] + \] @ (?: (? <clienthost> \ S *))? \ [(?: % {IP: clientip})? \] \ N # Query_time:% {NUMBER: query_time: float} \ s + Lock_time:% {NUMBER: lock_time: float} \ s + Rows_sent:% {NUMBER: rows_sent: int} \ s + Rows_examined:% {NUMBER: rows_examined: int} \ nSET \ s + timestamp =% {NUMBER: timestamp_mysql: int}; \ n (? <query>. *) "]
    }

    date {
        match => ["timestamp_mysql", "UNIX"]
        target => "@timestamp"
    }

}

output {
    elasticsearch {
        hosts => ["10.82.9.208:9200","10.82.9.217:9200"]
        index => "mysql-slowlog-% {+ YYYY.MM.dd}"
    }
}
Explanation of important parameters:
input: configure Kafka cluster address and topic name
filter: Filters log files. It mainly splits message information (see the log format received by Kafka above) and splits it into easy-to-read fields, such as User, Host, Query_time, Lock_time, timestamp, and so on. The grok segment matches the regular expressions that we could not write separately for the classification of the mysql slow log. When there are multiple regular expressions, logstash will be matched from top to bottom in order, and one that matches behind will no longer match. The date field defines the timestamp_mysql field in SQL as the time field of this log. The actual sorted data seen on kibana depends on this time.
output: Configure the address and index of the ES server cluster. The index is automatically divided by day.
kibana query display
Open Kibana and add the index of mysql-slowlog- *, and select timestamp to create the index pattern
Enter the Discover page, you can see the change of the number of slow logs at various points in time. You can implement simple filtering according to the left field. The search box is also convenient for searching slow logs. Enter query_time:> 2 in the search box
Click on the colored arrows at the beginning of each log to view the details of a specific log
If you want to make a large-scale statistics of the overall situation of slow logs, such as top 10 SQL, etc., you can also easily configure through the web interface
to sum up
Don't hold back, when you start to do it is half done
This article details the collection of mysql slow logs. What about the processing after collection? We are currently the DBA who spends time every day to check and analyze on Kibana. If there is room for optimization, we will communicate and optimize with the development. After reaching a tacit understanding, consider making an automatic alarm or processing.
The xpark about the alarm ELK ecology has been provided, and the latest version is also open source. If you are interested, you can research it first. Welcome to communicate together.