Uploaded image for project: 'MariaDB Server'
  1. MariaDB Server
  2. MDEV-9575

Slow logs empty until long_querys set to 0

    XMLWordPrintable

Details

    • Bug
    • Status: Closed (View Workflow)
    • Major
    • Resolution: Incomplete
    • 10.0.21-galera
    • N/A
    • OTHER
    • Distributor ID: Debian
      Description: Debian GNU/Linux 7.9 (wheezy)
      Release: 7.9
      Codename: wheezy

    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;
       

      Attachments

        1. my007.cnf
          4 kB
          darmagan
        2. my009.cnf
          5 kB
          darmagan
        3. my010.cnf
          13 kB
          darmagan
        4. my011.cnf
          13 kB
          darmagan
        5. my008.cnf
          4 kB
          darmagan
        6. my012.cnf
          14 kB
          darmagan

        Activity

          People

            Unassigned Unassigned
            da darmagan
            Votes:
            0 Vote for this issue
            Watchers:
            3 Start watching this issue

            Dates

              Created:
              Updated:
              Resolved:

              Git Integration

                Error rendering 'com.xiplink.jira.git.jira_git_plugin:git-issue-webpanel'. Please contact your Jira administrators.