[MDEV-9575] Slow logs empty until long_querys set to 0 Created: 2016-02-17  Updated: 2016-03-21  Resolved: 2016-03-21

Status: Closed
Project: MariaDB Server
Component/s: OTHER
Affects Version/s: 10.0.21-galera
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: darmagan Assignee: Unassigned
Resolution: Incomplete Votes: 0
Labels: need_feedback
Environment:

Distributor ID: Debian
Description: Debian GNU/Linux 7.9 (wheezy)
Release: 7.9
Codename: wheezy

Attachments: File my007.cnf     File my008.cnf     File my009.cnf     File my010.cnf     File my011.cnf     File my012.cnf    

 Description   

I have a multiple instance mariadb setup and the slow logs on all are not logging. And I know that there are queries longer than 2 seconds(long_query_time).

:/var/log/mysql# ls -l /var/log/mysql/
 
total 6408
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3306.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3306.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3306.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3306.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3306.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3306.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3306.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3306.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3307.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3307.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3307.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3307.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3307.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3307.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3307.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3307.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3308.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3308.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3308.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3308.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3308.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3308.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3308.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3308.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3310.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3310.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3310.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3310.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3310.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3310.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3310.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3310.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3311.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3311.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3311.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3311.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3311.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3311.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3311.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3311.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3312.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3312.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3312.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3312.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3312.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3312.slow.3.gz
 
-rw-r----- 1 mysql adm  459259 Jan 23 22:32 mysql_3312.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3312.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 14:53 mysql_3313.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3313.log.1
 
-rw-r----- 1 mysql adm 1058237 Feb 17 15:06 mysql_3313.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3313.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3313.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3313.slow.3.gz
 
-rw-r----- 1 mysql adm 4617045 Jan 24 06:32 mysql_3313.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3313.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3315.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3315.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3315.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3315.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3315.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3315.slow.3.gz
 
-rw-r----- 1 mysql adm      20 Jan 17 06:54 mysql_3315.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3315.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3316.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3316.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3316.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3316.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3316.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3316.slow.3.gz
 
-rw-r----- 1 mysql adm    1612 Jan 23 00:25 mysql_3316.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3316.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3317.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3317.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3317.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3317.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3317.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3317.slow.3.gz
 
-rw-r----- 1 mysql adm    1190 Jan 23 00:24 mysql_3317.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3317.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysql_3318.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysql_3318.log.1
 
-rw-r----- 1 mysql adm       0 Feb 14 06:37 mysql_3318.slow
 
-rw-r----- 1 mysql adm      20 Feb  7 06:43 mysql_3318.slow.1.gz
 
-rw-r----- 1 mysql adm      20 Jan 31 06:55 mysql_3318.slow.2.gz
 
-rw-r----- 1 mysql adm      20 Jan 24 06:32 mysql_3318.slow.3.gz
 
-rw-r----- 1 mysql adm     181 Jan 20 11:24 mysql_3318.slow.4.gz
 
-rw-r----- 1 mysql adm      20 Jan 10 06:37 mysql_3318.slow.5.gz
 
-rw-r----- 1 mysql adm       0 Feb 17 06:35 mysqld_multi.log
 
-rw-r----- 1 mysql adm       0 Feb 16 06:47 mysqld_multi.log.1
 
-rw-r----- 1 mysql adm    1525 Jan 27  2014 mysqld_multi.log.8.gz

this two variables I have set manually, without restarting the db.

| log_slow_filter                           |admin,filesort,filesort_on_disk,full_join,full_scan,query_cache,query_cache_miss,tmp_table,tmp_table_on_disk |
 
 
 
| long_query_time                                        | 2.000000   |

If I flush the logs on the instance and do a select sleep(3) the query is being logged:

# Time: 160217 15:17:30
 
# User@Host: root[root] @ localhost []
 
# Thread_id: 190290  Schema:   QC_hit: No
 
# Query_time: 3.000184  Lock_time: 0.000000  Rows_sent: 1  Rows_examined: 0
 
#
 
# explain: id   select_type     table   type    possible_keys   key     key_len ref     rows    Extra
 
# explain: 1    SIMPLE  NULL    NULL    NULL    NULL    NULL    NULL    NULL    No tables used
 
#
 
SET timestamp=1455718650;
 
select sleep(3);

But just that query is being logged. Now if I set the long_query_time to 0 sec, all queries are being logged. I see the ones that take longer than the 2 sec, in the logs, too. Now I set the long_query_time back to 2 sec again. Now the long queries are being logged normally, as they should:

# Time: 160217 15:17:43
 
# User@Host: test[test] @  [10.10.37.108]
 
# Thread_id: 189762  Schema: test  QC_hit: No
 
# Query_time: 4.249137  Lock_time: 0.000114  Rows_sent: 1  Rows_examined: 2067024
 
SET timestamp=1455718663;
 
select
 
                  min(archive.id) as id
 
                from
 
                  archive,
 
                  archivetemplate,
 
                  familydata,
 
                  (
 
                    select
 
                      jobactions.bookid 
                    from 
                      jobactions
 
                    where 
                      jobactions.info                            =  'Email Bestaetigung'
 
                    group by 
                       jobactions.bookid
 
                    having
 
                      adddate(max(jobactions.eventtime) , INTERVAL 1 DAY) < now()
 
                  ) jobactions
 
                where
 
                  archive.activeto                           is null                 and
 
                  archivetemplate.activeto                   is null                 and
 
                  archive.id                                 =  archivetemplate.id   and
 
                  archivetemplate.familyid                   =  familydata.id        and
 
                  archive.demo                               <> 1                    and
 
                  archive.locked                             <> 1                    and
 
                  archive.storno                             <> 1                    and
 
                  archive.anzeigenstatus                     in ('RELEASING')        and
 
                  familydata.visibleto                       >= date(now())          and
 
                  adddate(archive.datumzeit, INTERVAL 1 DAY) <  now()                and
 
                  archive.id                                 =  jobactions.bookid    and
 
                  archive.senddate is not null;
 
# Time: 160217 15:17:57
 
# User@Host: test[test] @  [10.10.37.108]
 
# Thread_id: 189766  Schema: test  QC_hit: No
 
# Query_time: 4.274134  Lock_time: 0.000135  Rows_sent: 1  Rows_examined: 2067024
 
SET timestamp=1455718677;
 
select
 
                  min(archive.id) as id
 
                from
 
                  archive,
 
                  archivetemplate,
 
                  familydata,
 
                  (
 
                    select
 
                      jobactions.bookid 
                    from 
                      jobactions
 
                    where 
                      jobactions.info                            =  'Email Bestaetigung'
 
                    group by 
                       jobactions.bookid
 
                    having
 
                      adddate(max(jobactions.eventtime) , INTERVAL 1 DAY) < now()
 
                  ) jobactions
 
                where
 
                  archive.activeto                           is null                 and
 
                  archivetemplate.activeto                   is null                 and
 
                  archive.id                                 =  archivetemplate.id   and
 
                  archivetemplate.familyid                   =  familydata.id        and
 
                  archive.demo                               <> 1                    and
 
                  archive.locked                             <> 1                    and
 
                  archive.storno                             <> 1                    and
 
                  archive.anzeigenstatus                     in ('RELEASING')        and
 
                  familydata.visibleto                       >= date(now())          and
 
                  adddate(archive.datumzeit, INTERVAL 1 DAY) <  now()                and
 
                  archive.id                                 =  jobactions.bookid    and
 
                  archive.senddate is not null;
 
 



 Comments   
Comment by Elena Stepanova [ 2016-02-17 ]

da,

How exactly do you set long_query_time manually? Please paste the command.
What happens if you add it to the cnf file instead?

Also, please note that the attached cnf file does not correspond the ls output that you pasted in the description, apparently they are from different instances.

Comment by darmagan [ 2016-02-18 ]

I have attached the my.cnf of all servers. The ls output of all servers look like that(slow_logs empty).

I set the long_query_time with:
set global long_query_time=2;
set session long_query_time=2;

In the separated conf file I have added the changes, too. It looks like this:
[mysqld]
long_query_time = 2
expire_logs_days = 14
innodb_file_format = "barracuda"

I have included the conf with !includedir for all my.cnf files:
!includedir /etc/mysql/conf.d/

I have set them manually, because I dont want to restart the servers. (I have not restarted them since the changes).

Also, I have set the following vars manually:
set global expire_logs_days=14;
set global innodb_file_format='Barracuda';

With show variables, I see the vars are set to the right values.

Comment by Elena Stepanova [ 2016-02-22 ]

da,
So far I couldn't reproduce behavior that you're describing. However, there might be an explanation that you should consider.

As you know, long_query_time and slow_query_log are both global and session variables. Importantly, it means that when you change the global value, this change does not affect already existing connections – only new ones will pick up the value. flush logs does not help here. So, if your workflow is such that the connections running long queries are fairly persistent, it could be that you set the values, but they are not picked up for some time. You ran your test sleep query in the same connection where you set both session and global values (or in a newer one, which picked up the new global value), so naturally it was logged. While you were experimenting with zero value, a new connection was established and started running slow queries, so you got them in the log.

Now, I don't have enough data to check if it's really your case or not. You can get a good enough idea if it's so by comparing connection IDs in the slow log – only connections newer than the one you changed the values in would appear in the log. Please let us know what you find out.

Comment by Elena Stepanova [ 2016-03-21 ]

Please comment to re-open if you have further information on the issue.

Generated at Thu Feb 08 07:35:43 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.