Skip to:

  1. Skip to Jira Navigation
  2. Skip to Side Navigation
  3. Skip to Main Content

LP #1490028: slow_query_log_always_write_time doesn't work

Description

**Reported in Launchpad by Daniel Nichter last update 16-09-2015 14:25:10

Using Percona Server 5.5.41-37.0,

mysql> select @@global.slow_query_log_always_write_time;
-------------------------------------------

@@global.slow_query_log_always_write_time

-------------------------------------------

10.000000

-------------------------------------------

mysql> show global variables like 'log_slow_rate%';
----------------------------+

Variable_name

Value

----------------------------+

log_slow_rate_limit

10

log_slow_rate_type

query

----------------------------+

Then I cause a query to wait for a lock so its exec time becomes > 10s. When the lock frees and the query finally executes (e.g. 20s later), it is not logged to the slow log.

Environment

None

Smart Checklist

Activity

lpjirasync January 24, 2018 at 8:29 AM

**Comment from Launchpad by: Yura Sorokin on: 16-09-2015 14:25:10

As per https://bugs.mysql.com/bug.php?id=71767 comments
This is not a bug. Locking time is deliberately not taken into account when determining whether a statement should be written to the slow query log.

http://dev.mysql.com/doc/refman/5.6/en/slow-query-log.html: "The time to acquire the initial locks is not counted as execution time. mysqld writes a statement to the slow query log after it has been executed and after all locks have been released, so log order might differ from execution order. "

lpjirasync January 24, 2018 at 8:29 AM

**Comment from Launchpad by: Yura Sorokin on: 11-09-2015 19:28:26

Created a test case to reproduce the problem
https://github.com/percona-ysorokin/percona-server/commit/6bc5902403dd5dd9b92929a755735af22384ea07?diff=unified

1. Create a table.
2. Insert a few records into a table.
3. Set global slow query log parameters as in description.
4. Initiate another connection and lock the table from (1) there in "WRITE" mode.
5. Switch to primary connection.
6. Enable slow query log.
7. Send "SELECT * FROM <table>" command asynchronously ("--send xxx").
8. Switch to another connection from (the same as in (4)).
9. Wait 11 seconds.
10. Unlock the table.
11. Switch to primary connection.
12. Wait for "SELECT" statement from (7) to finish.
13. Grab slow query log output and make sure the "SELECT" statement from (7) is there.

lpjirasync January 24, 2018 at 8:29 AM

**Comment from Launchpad by: Laurynas Biveinis on: 29-08-2015 09:01:23

This could be related to other slow query log bugs that manifest as MTR tests failing (because something is not logged)

Done

Details

Assignee

Reporter

Labels

Priority

Smart Checklist

Created January 24, 2018 at 8:28 AM
Updated January 24, 2018 at 8:29 AM
Resolved January 24, 2018 at 8:29 AM