The last article “small and medium-sized teams quickly build SQL automatic audit system” we completed the automatic audit and execution of SQL, not only improve the efficiency but also by colleagues of the affirmation, the heart is elated. However, the collection and processing of slow queries also cost us too much time and energy. How can we improve efficiency in this area? This article explains how to use ELK for slow log collection

ELK is introduced

ELK was originally the name of Elasticsearch (ES), Logstash, and Kibana, which was later acquired by the same company and incorporated into Xpark, Beats, and Other components. Renamed Elastic Stack, ELK is now the most popular open-source log solution. Despite the new name, she is still known as ELK, which now refers to the logging system built on these open-source software.

Mysql > collect slow logs

Mysql server install Filebeat as agent to collect slowLog
Filebeat reads slow mysql log files for simple filtering to Kafka cluster
Logstash reads Kafka cluster data and splits it into JSON format and stores it in ES cluster
Kibana reads ES cluster data and displays it on the Web page

Slow Log Classification

Currently, the main mysql versions are 5.5, 5.6 and 5.7. After careful comparison, it is found that the slow query logs of each version are slightly different as follows:

5.5 Slow Query logs

# 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';
Copy the code

5.6 Slow Query logs

# 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;
Copy the code

5.7 Slow Log Query

T10 # Time: 2018-07-09:04:14. 666231 z
# 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;
Copy the code

Similarities and differences of slow query logs:

The format of the Time field varies from version to version
The Id field is missing in version 5.5 compared to version 5.6 and 5.7
use dbStatements are not available for every slow log
There may be situations like the following, slow query blocks# Time:The following may follow multiple slow query statements

# 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');
Copy the code

Processing way of thinking

We have analyzed each version of the slow query statement composition, next we will start to collect this data, exactly how to collect?

Assemble log lines: The slow query log lines of mysql form a complete log. When collecting logs, assemble these lines into a log for transmission and storage.
Time line processing:# Time:The opening line may not exist and we can passSET timestampThis value determines the SQL execution Time, so the filter discard Time line is selected
A complete log: will eventually be# User@Host:The beginning line and the end line of the SQL statement are merged into a complete slow log statement
Select DB from SQL;use dbNot all slow log SQL exists in this line, so you cannot use this line to determine the DB of the SQL, and there is no field in the slow log to record the DB, so it is recommendedAdd the DB name identifier when creating an account for DBFor example, our account name is:projectName_dbName, so that you can see the account name to know which DB
Determine the host to which the SQL corresponds: What if I want to know which database server the SQL corresponds to from the log? There is also no field to record the host in the slow log, which can be solved by the FileBeat injection field. For example, we set the name field of FileBeat to the server IP address, and finally passbeat.nameThis field determines the host to which the SQL corresponds

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: trueName: 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
Copy the code

Important parameters:

Input_type: specifies whether the input type is log or stdin
Paths: slow log paths that support regulars such as /data/*.log
exclude_lines: to filter out# TimeThe beginning of the line
multiline.pattern: Specifies the regular expression to match multiple lines, where matches with# Timeor# UserThe leading line, the Time line, is matched before filtering
Multiline. negate: defines whether the rows in the pattern matched above are used for multi-line merging, that is, whether they are part of the log
Multiline. match: defines how to combine skin rankings into times, before or after
Tail_files: defines whether to read logs from the beginning of a file or from the end of a file, defined as true, and collected from now on regardless of existing logs
Name: Sets fileBeat’s name. If it is empty, it is the host name of the server, which we define as the server IP
Output. kafka: Specifies the address and topic name of the Kafka cluster to receive logs

Kafka receives logs in the following format:

{"@timestamp":"The 2018-08-07 T09:36:00. 140 z"."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"}
Copy the code

Logstash configuration

The complete logstash configuration file 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}\[[^\]]+\] @ (? : (? 
      
       \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(? 
       
        \w+); \nSET\s+timestamp=%{NUMBER:timestamp_mysql:int}; \n(? 
        
         .*)"
        
       
       ]

        # ID has no use
        match => [ "message"."(? m)^# User@Host: %{USER:user}\[[^\]]+\] @ (? : (? 
      
       \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(? 
       
        .*)"
       
       ]

        None ID Indicates use
        match => [ "message"."(? m)^# User@Host: %{USER:user}\[[^\]]+\] @ (? : (? 
      
       \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(? 
       
        \w+); \nSET\s+timestamp=%{NUMBER:timestamp_mysql:int}; \n(? 
        
         .*)"
        
       
       ]

        None ID No use
        match => [ "message"."(? m)^# User@Host: %{USER:user}\[[^\]]+\] @ (? : (? 
      
       \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(? 
       
        .*)"
       
       ]
    }

    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}"}}Copy the code

Important parameters:

Input: Sets the kafka cluster address and topic name
filterFilter log files by splitting the message (see above) into readable fields, such asUser,Host,Query_time,Lock_time,timestampAnd so on. The grok segment is matched according to the classification of mysql slow log as described above. When there are multiple regular expressions, the Logstash segment will be matched from top to bottom, and the following one will not be matched. The date field defines the timestamp_mysql field in SQL as the time field for this log, which is what the practice sorting data seen on Kibana depends on
Output: Sets the ADDRESS and index of the ES server cluster. The index is automatically divided by day

Kibana query display

Open Kibana add mysql-slowlog-* Index and select timestamp to create Index Pattern
On the Discover page, you can see the changes in the number of slow logs at each point in time. Simple filtering can be implemented according to the Field on the left. The search box is also convenient for searching slow logs
Click the colored arrow at the top of each entry to view details of a specific entry
If you want to do a large number of slow log statistics overall situation, such as top 10 SQL, can also be easily configured through the Web interface

conclusion

Don’t stop. You’re halfway there when you start
This article introduces the collection of mysql slow logs. At present, we are DBAs who spend time to check analysis on Kibana every day. If there is room for optimization, we will communicate and optimize with the developer. After reaching a tacit understanding, we will consider automatic alarm or processing
Xpark about alarm ELK ecology has been provided, and the latest version is also open source, those who are interested can study first, welcome to communicate with us

Related articles are recommended reading

The principle and application of ELK system in production environment
General application log access scheme for ELK log system
Kafka Group is used to realize high availability of Logstash under ELK architecture

mo4tech.com (Moment For Technology) is a global community with thousands techies from across the global hang out!Passionate technologists, be it gadget freaks, tech enthusiasts, coders, technopreneurs, or CIOs, you would find them all here.

ELK build MySQL slow log collection platform details

ELK is introduced

Slow Log Classification

Processing way of thinking

Filebeat configuration

Important parameters:

Kafka receives logs in the following format:

Logstash configuration

Important parameters:

Kibana query display

conclusion

ELK build MySQL slow log collection platform details

ELK is introduced

Slow Log Classification

Processing way of thinking

Filebeat configuration

Important parameters:

Kafka receives logs in the following format:

Logstash configuration

Important parameters:

Kibana query display

conclusion

Related Posts

Concurrency in GO

Vue custom alertTip component, Go simple use of email

High concurrency large capacity NoSQL solution exploration