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

          Attachments

            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