[MDEV-19247] slow query log won't log queries for existing client sessions Created: 2019-04-12  Updated: 2019-04-19  Resolved: 2019-04-17

Status: Closed
Project: MariaDB Server
Component/s: Storage Engine - InnoDB
Affects Version/s: 10.1.38
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Christopher Lewis Marshall Assignee: Unassigned
Resolution: Not a Bug Votes: 0
Labels: None
Environment:

verified in docker containers


 Description   

I have verified this bug (in the strong form described) in docker images mysql:5.5, mariadb:10.4.4-bionic, mariadb:10.1.38-bionic, and mariadb:5.5.63-trusty. It exists in a weaker form in mariadb:10.0.38-xenial and mysql:5.5.

When using the following docker-compose.yml to bring up a container running mysqld:

version: '3'
 
services:
 
  db:
 
    image: "mariadb:10.4.4-bionic"
 
#    image: "mariadb:10.1.38-bionic"
 
#    image: "mariadb:10.0.38-xenial"
 
#    image: "mariadb:5.5.63-trusty"
 
#    image: "mysql:5.5"
 
    restart: always
 
    environment:
 
      MYSQL_ROOT_PASSWORD: somepass

I open mysql client sessions 1 and 2. In session 1, I turn on slow query logging with:

set global log_output = 'FILE';
 
set global long_query_time = 0;
 
set global slow_query_log = 'ON';

Then I open client session 3. In session 2 I run a simple query:

select sleep(1.1);

and in session 3, I run:

select sleep(1.2);

and then in session 2, I run:

select sleep(1.3);

I then turn off slow query logging in session 1:

set global slow_query_log = 'OFF';

inspecting the slow query log in /var/log/mysql, only the sleep(1.2) was logged.

The consequence of this is that in a system where processes keep client sessions open for long periods, slow query logging can not determine if those processes are causing issues unless they are bounced (or have their connections killed and have to reestablish them). That can rather disruptive.

 Comments   
Comment by Sergei Golubchik [ 2019-04-17 ]

This is expected behavior. For a query to be logged in a slow log, both global and session slow_query_log must be ON.

A session variable gets it value from a global variable when a session is created. So every connection that started when @@global.slow_query_log=OFF, will have @@session.slow_query_log=OFF. Changing global slow_query_log value will not affect session variables of already running sessions.

Comment by Christopher Lewis Marshall [ 2019-04-17 ]

Sergi:

Thanks for clarifying the behavior. Is there any way, on a system with multiple long running sessions, to turn on slow query logging so that you can find the queries consuming the most elapsed time and causing the most contention?

I realize that running tcpdump to capture all server traffic and using a tool like pt-query-digest to recreate the slow query log from that is one way, but I believe that would not give as much information about the time spent in lock wait as the internal slow query logging of mariadb.

Chris M

Comment by Sergei Golubchik [ 2019-04-19 ]

Performance_schema could help, if you have it enabled. SHOW EXPLAIN could help to find bad query plans, but not log waits. metadata_lock_info plugin could be used to analyze, well, metadata locks.

But this is outside of scope of this bug report, please ask on maria-discuss@lists.launchpad.net

Generated at Thu Feb 08 08:50:10 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.