Working as a Percona Support Engineer, every day we are seeing lots of issues related to MySQL replication. One very common issue is slave lagging. There are many reasons for slave lag but one common reason is that queries are taking more time on slave then master. How to check and log those long-running queries? From MySQL 5.1, log-slow-slave-statements variable was introduced, which you can enable on slave and log slow queries. But what if you want to log slow queries on slave in earlier versions like MySQL 5.0? There is a good solution/workaround: pt-query-digest. How? let’s take a look….
If you want to log all queries that are running on slave (including those, running by sql thread), you can use pt-query-digest with —processlist and –print (In pt-query-digest 2.1.9) OR –output (In pt-query-digest 2.2.7) options and log all queries in specific file. I have tested it in my local environment and it works.
You can start pt-query-digest like below on Slave,
|
1 2 3 4 5 |
nil@Dell:~$ /percona-toolkit-2.1.9/bin/pt-query-digest --processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock --print --no-report OR nil@Dell:-$ /percona-toolkit-2.2.7/bin/pt-query-digest --processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock --no-report --output=slowlog |
Run some long running queries on Master,
|
1 2 3 4 5 6 7 8 9 10 11 |
nil@Dell:~$ mysql -umsandbox -p --socket=/tmp/mysql_sandbox34497.sock Enter password: mysql> use percona Reading table information for completion of table and column names You can turn off this feature to get a quicker startup with -A Database changed mysql> delete from test limit 5000000; Query OK, 5000000 rows affected (1 min 54.33 sec) mysql> delete from test limit 5000000; Query OK, 5000000 rows affected (1 min 56.42 sec) |
mysql>
and you’ll see the output on Slave like this,
|
1 2 3 4 5 6 7 8 9 10 11 12 13 |
nil@Dell:~/Downloads/percona-toolkit-2.1.9/bin$ ./pt-query-digest --processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock --print --no-report # Time: 2014-03-18T12:10:57 # User@Host: system user[system user] @ [] # Query_time: 114.000000 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 use percona; delete from test limit 5000000; nil@Dell:~/Downloads/percona-toolkit-2.2.7/bin$ pt-query-digest --processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock --no-report --output=slowlog # Time: 2014-03-18T12:21:05 # User@Host: system user[system user] @ [] # Query_time: 117.000000 Lock_time: 0.000000 Rows_sent: 0 Rows_examined: 0 use percona; delete from test limit 5000000; |
You can also run pt-query-digest in background like a daemon and send output to the specific file like slow.log and review it.
i.e /percona-toolkit-2.1.9/bin/pt-query-digest –processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock –print –no-report > slow.log 2>&1
OR
i.e /percona-toolkit-2.2.7/bin/pt-query-digest –processlist u=msandbox,p=msandbox,S=/tmp/mysql_sandbox34498.sock –no-report –output=slowlog > slow.log 2>&1
Here, the default output will be just like slow query log. If we have master-master replication where every master is slave too and we want to log only those statements that are executing by sql_thread then –filter option can be used like this:
pt-query-digest –filter ‘$event->user eq “system user”‘ –no-report –output=slowlog
Since pt-query-digest–processlist polls 10 times/second ( –interval option), it’s not reliable to use for collecting complete query logs, because quick queries could fall in between the polling intervals. And in any case, it won’t measure query time with precision any better than 1/10th of a second. But if the goal is to identify queries that are very long-running, it should be adequate.
Comment (1)
Hi All ,
I am facing replication lag even I’m using multi thread replication could you please help to reduce the replication lag . it seems issue with SQL thread because I am getting SQL state Waiting for dependent transaction to commit
If someone help then it would be great help .
Slave_IO_State: Waiting for master to send event
Master_Host: 10.140.2.69
Master_User: repl
Master_Port: 3330
Connect_Retry: 60
Master_Log_File: mysql-bin.000360
Read_Master_Log_Pos: 745241233
Relay_Log_File: relay-log.000166
Relay_Log_Pos: 587394954
Relay_Master_Log_File: mysql-bin.000326
Slave_IO_Running: Yes
Slave_SQL_Running: Yes
Replicate_Do_DB:
Replicate_Ignore_DB:
Replicate_Do_Table:
Replicate_Ignore_Table:
Replicate_Wild_Do_Table: urapport_contact.%
Replicate_Wild_Ignore_Table: mysql.%,test.%,information_schema.%,performance_schema.%
Last_Errno: 0
Last_Error:
Skip_Counter: 0
Exec_Master_Log_Pos: 587394741
Relay_Log_Space: 37252499844
Until_Condition: None
Until_Log_File:
Until_Log_Pos: 0
Master_SSL_Allowed: No
Master_SSL_CA_File:
Master_SSL_CA_Path:
Master_SSL_Cert:
Master_SSL_Cipher:
Master_SSL_Key:
Seconds_Behind_Master: 534243
Master_SSL_Verify_Server_Cert: No
Last_IO_Errno: 0
Last_IO_Error:
Last_SQL_Errno: 0
Last_SQL_Error:
Replicate_Ignore_Server_Ids:
Master_Server_Id: 693330
Master_UUID: b753362d-abe6-11e6-8cbc-8cdcd4b0b20d
Master_Info_File: mysql.slave_master_info
SQL_Delay: 0
SQL_Remaining_Delay: NULL
Slave_SQL_Running_State: Waiting for dependent transaction to commit
Master_Retry_Count: 86400