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

information_schema.processlist reports incorrect value for Time (2147483647)

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Minor
    • Resolution: Fixed
    • Affects Version/s: 10.0.2, 5.5.31, 5.1.67, 5.2.14, 5.3.12
    • Fix Version/s: 10.0.4, 5.5.32
    • Component/s: None
    • Labels:
      None
    • Environment:
      Debian Squeeze (6.0.6) x86_64, Linux 3.2.40. Compiled locally. This is 5.5.28-MariaDB-log.

      Description

      In the information_schema.processlist table, the Time column frequently reports an incorrect value of 2147483647. "show processlist" is not similarly affected. From my testing, I'm reasonably sure these queries are all less than 1 second old. I do see plenty of processes reported with an accurate Time value (>=1).

      Examples (with some obfuscation):

      *************************** 1. row ***************************
             ID: 81365
           USER: xxx
           HOST: xxx
             DB: xxx
        COMMAND: Query
           TIME: 2147483647
          STATE: Sending data
           INFO: select xxx left outer join xxx on xxx where xxx
        TIME_MS: 18446744073709550.000
          STAGE: 0
      MAX_STAGE: 0
       PROGRESS: 0.000
      
      *************************** 1. row ***************************
             ID: 82602
           USER: xxx
           HOST: xxx
             DB: xxx
        COMMAND: Query
           TIME: 2147483647
          STATE: optimizing
           INFO: select xxx from xxx where xxx
        TIME_MS: 18446744073709550.000
          STAGE: 0
      MAX_STAGE: 0
       PROGRESS: 0.000
      

        Gliffy Diagrams

          Issue Links

            Activity

            Hide
            elenst Elena Stepanova added a comment -

            Hi Jonathan,

            It's not quite clear from the description, do you ever see processes with accurate time less than 1 sec, or are all of those always damaged?

            Thanks.

            Show
            elenst Elena Stepanova added a comment - Hi Jonathan, It's not quite clear from the description, do you ever see processes with accurate time less than 1 sec, or are all of those always damaged? Thanks.
            Hide
            jnicol Jonathan Nicol added a comment -

            I see processes with times of 0, 1, 2, etc. I'm just making an educated guess based on the specific affected queries that they are less than 1 second old.

            Show
            jnicol Jonathan Nicol added a comment - I see processes with times of 0, 1, 2, etc. I'm just making an educated guess based on the specific affected queries that they are less than 1 second old.
            Hide
            jnicol Jonathan Nicol added a comment -

            to be clear, here's an example of an accurate one:

            *************************** 1. row ***************************
                   ID: 87448
                 USER: xxx
                 HOST: xxx
                   DB: xxx
              COMMAND: Query
                 TIME: 0
                STATE: Sending data
                 INFO: select xxx from xxx inner join xxx on xxx left outer join xxx on xxx inner join xxx on xxx where xxx limit 100
              TIME_MS: 976.187
                STAGE: 0
            MAX_STAGE: 0
             PROGRESS: 0.000
            
            Show
            jnicol Jonathan Nicol added a comment - to be clear, here's an example of an accurate one: *************************** 1. row *************************** ID: 87448 USER: xxx HOST: xxx DB: xxx COMMAND: Query TIME: 0 STATE: Sending data INFO: select xxx from xxx inner join xxx on xxx left outer join xxx on xxx inner join xxx on xxx where xxx limit 100 TIME_MS: 976.187 STAGE: 0 MAX_STAGE: 0 PROGRESS: 0.000
            Hide
            elenst Elena Stepanova added a comment -

            Hi Jonathan,

            Thank you. I'm able to repeat the problem with a concurrent test, I'll see if I can make it more deterministic.

            Show
            elenst Elena Stepanova added a comment - Hi Jonathan, Thank you. I'm able to repeat the problem with a concurrent test, I'll see if I can make it more deterministic.
            Hide
            elenst Elena Stepanova added a comment -
            1. Test case with sync points:

            source include/have_debug_sync.inc;

            SET DEBUG_SYNC = 'dispatch_command_before_set_time WAIT_FOR do_set_time';
            send SELECT 1;

            connect (con1,localhost,root,,);

            SET DEBUG_SYNC = 'fill_schema_processlist_after_unow SIGNAL do_set_time WAIT_FOR fill_schema_proceed';
            send SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST;

            connection default;
            reap;
            SET DEBUG_SYNC = 'now SIGNAL fill_schema_proceed';

            connection con1;
            vertical_results;
            reap;
            horizontal_results;
            disconnect con1;

            1. End of test case
              ===========================================
            1. Test output:

            SET DEBUG_SYNC = 'dispatch_command_before_set_time WAIT_FOR do_set_time';
            SELECT 1;
            SET DEBUG_SYNC = 'fill_schema_processlist_after_unow SIGNAL do_set_time WAIT_FOR fill_schema_proceed';
            SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST;
            1
            1
            SET DEBUG_SYNC = 'now SIGNAL fill_schema_proceed';
            ID 3
            USER root
            HOST localhost
            DB test
            COMMAND Query
            TIME 0
            STATE executing
            INFO SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST
            TIME_MS 0.849
            STAGE 0
            MAX_STAGE 0
            PROGRESS 0.000
            ID 2
            USER root
            HOST localhost
            DB test
            COMMAND Sleep
            TIME 2147483647
            STATE
            INFO NULL
            TIME_MS 18446744073709550.000
            STAGE 0
            MAX_STAGE 0
            PROGRESS 0.000

            1. End of test output

            ===========================================

            1. Patch for adding sync points (based on maria/5.5 revno 3779), also attached to the issue as mdev4578_debug_sync.patch:

            cat mdev4578_debug_sync.patch
            === modified file 'sql/sql_parse.cc'
            — sql/sql_parse.cc 2013-05-08 18:37:17 +0000
            +++ sql/sql_parse.cc 2013-05-27 00:50:02 +0000
            @@ -914,6 +914,9 @@
            thd->enable_slow_log= TRUE;
            thd->query_plan_flags= QPLAN_INIT;
            thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */
            +
            + DEBUG_SYNC(thd,"dispatch_command_before_set_time");
            +
            thd->set_time();
            thd->set_query_id(get_query_id());
            if (!(server_command_flags[command] & CF_SKIP_QUERY_ID))

            === modified file 'sql/sql_show.cc'
            — sql/sql_show.cc 2013-05-11 17:31:50 +0000
            +++ sql/sql_show.cc 2013-05-27 00:51:16 +0000
            @@ -2297,6 +2297,8 @@
            my_hrtime_t unow= my_hrtime();
            DBUG_ENTER("fill_schema_processlist");

            + DEBUG_SYNC(thd,"fill_schema_processlist_after_unow");
            +
            user= thd->security_ctx->master_access & PROCESS_ACL ?
            NullS : thd->security_ctx->priv_user;

            Show
            elenst Elena Stepanova added a comment - Test case with sync points: source include/have_debug_sync.inc; SET DEBUG_SYNC = 'dispatch_command_before_set_time WAIT_FOR do_set_time'; send SELECT 1; connect (con1,localhost,root,,); SET DEBUG_SYNC = 'fill_schema_processlist_after_unow SIGNAL do_set_time WAIT_FOR fill_schema_proceed'; send SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST; connection default; reap; SET DEBUG_SYNC = 'now SIGNAL fill_schema_proceed'; connection con1; vertical_results; reap; horizontal_results; disconnect con1; End of test case =========================================== Test output: SET DEBUG_SYNC = 'dispatch_command_before_set_time WAIT_FOR do_set_time'; SELECT 1; SET DEBUG_SYNC = 'fill_schema_processlist_after_unow SIGNAL do_set_time WAIT_FOR fill_schema_proceed'; SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST; 1 1 SET DEBUG_SYNC = 'now SIGNAL fill_schema_proceed'; ID 3 USER root HOST localhost DB test COMMAND Query TIME 0 STATE executing INFO SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST TIME_MS 0.849 STAGE 0 MAX_STAGE 0 PROGRESS 0.000 ID 2 USER root HOST localhost DB test COMMAND Sleep TIME 2147483647 STATE INFO NULL TIME_MS 18446744073709550.000 STAGE 0 MAX_STAGE 0 PROGRESS 0.000 End of test output =========================================== Patch for adding sync points (based on maria/5.5 revno 3779), also attached to the issue as mdev4578_debug_sync.patch: cat mdev4578_debug_sync.patch === modified file 'sql/sql_parse.cc' — sql/sql_parse.cc 2013-05-08 18:37:17 +0000 +++ sql/sql_parse.cc 2013-05-27 00:50:02 +0000 @@ -914,6 +914,9 @@ thd->enable_slow_log= TRUE; thd->query_plan_flags= QPLAN_INIT; thd->lex->sql_command= SQLCOM_END; /* to avoid confusing VIEW detectors */ + + DEBUG_SYNC(thd,"dispatch_command_before_set_time"); + thd->set_time(); thd->set_query_id(get_query_id()); if (!(server_command_flags [command] & CF_SKIP_QUERY_ID)) === modified file 'sql/sql_show.cc' — sql/sql_show.cc 2013-05-11 17:31:50 +0000 +++ sql/sql_show.cc 2013-05-27 00:51:16 +0000 @@ -2297,6 +2297,8 @@ my_hrtime_t unow= my_hrtime(); DBUG_ENTER("fill_schema_processlist"); + DEBUG_SYNC(thd,"fill_schema_processlist_after_unow"); + user= thd->security_ctx->master_access & PROCESS_ACL ? NullS : thd->security_ctx->priv_user;

              People

              • Assignee:
                serg Sergei Golubchik
                Reporter:
                jnicol Jonathan Nicol
              • Votes:
                0 Vote for this issue
                Watchers:
                3 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0 minutes
                  0m
                  Logged:
                  Time Spent - 40 minutes
                  40m