MariaDB Development
  1. MariaDB Development
  2. MDEV-4578

information_schema.processlist reports incorrect value for Time (2147483647)

    Details

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

      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
      

        Issue Links

          Activity

          Hide
          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
          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
          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
          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
          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
          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
          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
          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
          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
          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:
              Sergei Golubchik
              Reporter:
              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