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

INFORMATION_SCHEMA.PROCESSLIST reports an incorrect value for Time for connecting threads

Details

    • Bug
    • Status: Closed (View Workflow)
    • Minor
    • Resolution: Fixed
    • 10.0.4, 5.5.33a
    • 5.5.34, 10.0.6
    • None
    • Debian Wheezy amd64
      MariaDB 5.5.32 official binary (not the Debian packaged version)

    Description

      In the INFORMATION_SCHEMA.PROCESSLIST table, the Time column reports the actual UNIX timestamp for new connections instead of a NULL value like the SHOW PROCESSLIST (or a duration) like it should.

      Examples from a server having an important number or connections/seconds :

      user@host:~# /bin/mksh -c 'i=0; while ((i < 200)); do BUG="$(mysql -Ne "SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST WHERE USER like \"unauthen%\";")"; [[ -n "$BUG" ]] && print "I_S: $BUG" && print "SHOW: $(mysql -e "SHOW FULL PROCESSLIST;" |grep unau)\nTIMESTAMP: $(date +%s)\n"; sleep .05; ((i++)); done'
      		 
      I_S: 788377361	unauthenticated user	192.168.49.162:38772	NULL	Connect	1380896552	Reading from net	NULL	1380896552152.118	0	0	0.000
      		 
      788377355	unauthenticated user	192.168.39.123:48828	NULL	Connect	1380896552	Reading from net	NULL	1380896552152.118	0	0	0.000
      		 
      SHOW: 788377355	unauthenticated user	192.168.39.123:48828	NULL	Connect	NULL	Reading from net	NULL	0.000
      		 
      788377367	unauthenticated user	192.168.38.143:56011	NULL	Connect	NULL	Reading from net	NULL	0.000
      		 
      788377368	unauthenticated user	192.168.35.174:38835	NULL	Connect	NULL	Reading from net	NULL	0.000
      		 
      TIMESTAMP: 1380896552
      		 
       
      		 
      I_S: 788414352	unauthenticated user	connecting host	NULL	Connect	1380896751	login	NULL	1380896751439.210	0	0	0.000
      		 
      SHOW: 788414355	unauthenticated user	connecting host	NULL	Connect	NULL	login	NULL	0.000
      		 
      TIMESTAMP: 1380896751
      		 
       
      		 
      I_S: 788490446	unauthenticated user	192.168.39.24:46534	NULL	Connect	1380897163	Reading from net	NULL	1380897163496.970	0	0	0.000
      		 
      SHOW: 788490447	unauthenticated user	connecting host	NULL	Connect	NULL	login	NULL	0.000
      		 
      TIMESTAMP: 1380897163
      		 
       
      		 
      I_S: 788490911	unauthenticated user	192.168.40.201:55249	NULL	Connect	1380897165	Reading from net	NULL	1380897165571.172	0	0	0.000
      		 
      SHOW: 788490918	unauthenticated user	192.168.48.247:55195	NULL	Connect	NULL	Reading from net	NULL	0.000
      		 
      TIMESTAMP: 1380897165

      We can see that the Time column on I_S (as well as the Time_MS column) always reports the actual timestamp and not a duration (or a NULL value like the SHOW PROCESSLIST does) as it should.

      ps: MySQL 5.5.30 and 5.5.28 doesnt seems to have this bug (they return 0 as the Time value on I_S.PROCESSLIST for these connecting threads).

      Attachments

        Issue Links

          relates to

          Bug - A problem which impairs or prevents the functions of the product. MDEV-4578 information_schema.processlist reports incorrect value for Time (2147483647)

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Closed

          Bug - A problem which impairs or prevents the functions of the product. MDEV-4673 PROCESSLIST time in processlist is very high (maybe time = 0 setted and unsigned overflow?)

          • Minor - Minor loss of function, or other problem where easy workaround is present.
          • Closed

          Activity

            Ascending order - Click to sort in descending order
            jb-boin Jean Weisbuch created issue -
            jb-boin Jean Weisbuch made changes -
            Field Original Value New Value
            jb-boin Jean Weisbuch made changes -
            jb-boin Jean Weisbuch made changes -
            Description In the INFORMATION_SCHEMA.PROCESSLIST table, the Time column reports the actual UNIX timestamp for new connections instead of a NULL value like the SHOW PROCESSLIST (or a duration) like it should.

            Examples from a server having an important number or connections/seconds :
            {noformat}user@host:~# /bin/mksh -c 'i=0; while ((i < 200)); do BUG="$(mysql -Ne "SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST WHERE USER like \"unauthen%\";")"; [[ -n "$BUG" ]] && print "I_S: $BUG" && print "SHOW: $(mysql -e "SHOW FULL PROCESSLIST;" |grep unau)\nTIMESTAMP: $(date +%s)\n"; sleep .05; ((i++)); done'
            I_S: 788377361 unauthenticated user 192.168.49.162:38772 NULL Connect 1380896552 Reading from net NULL 1380896552152.118 0 0 0.000
            788377355 unauthenticated user 192.168.39.123:48828 NULL Connect 1380896552 Reading from net NULL 1380896552152.118 0 0 0.000
            SHOW: 788377355 unauthenticated user 192.168.39.123:48828 NULL Connect NULL Reading from net NULL 0.000
            788377367 unauthenticated user 192.168.38.143:56011 NULL Connect NULL Reading from net NULL 0.000
            788377368 unauthenticated user 192.168.35.174:38835 NULL Connect NULL Reading from net NULL 0.000
            TIMESTAMP: 1380896552

            I_S: 788414352 unauthenticated user connecting host NULL Connect 1380896751 login NULL 1380896751439.210 0 0 0.000
            SHOW: 788414355 unauthenticated user connecting host NULL Connect NULL login NULL 0.000
            TIMESTAMP: 1380896751

            I_S: 788490446 unauthenticated user 192.168.39.24:46534 NULL Connect 1380897163 Reading from net NULL 1380897163496.970 0 0 0.000
            SHOW: 788490447 unauthenticated user connecting host NULL Connect NULL login NULL 0.000
            TIMESTAMP: 1380897163

            I_S: 788490911 unauthenticated user 192.168.40.201:55249 NULL Connect 1380897165 Reading from net NULL 1380897165571.172 0 0 0.000
            SHOW: 788490918 unauthenticated user 192.168.48.247:55195 NULL Connect NULL Reading from net NULL 0.000
            TIMESTAMP: 1380897165{noformat}

            We can see that the Time column on I_S (as well as the Time_MS column) always reports the actual timestamp and not a duration (or a NULL value like the SHOW PROCESSLIST does) as it should.             		In the INFORMATION_SCHEMA.PROCESSLIST table, the Time column reports the actual UNIX timestamp for new connections instead of a NULL value like the SHOW PROCESSLIST (or a duration) like it should.

            Examples from a server having an important number or connections/seconds :
            {noformat}user@host:~# /bin/mksh -c 'i=0; while ((i < 200)); do BUG="$(mysql -Ne "SELECT * FROM INFORMATION_SCHEMA.PROCESSLIST WHERE USER like \"unauthen%\";")"; [[ -n "$BUG" ]] && print "I_S: $BUG" && print "SHOW: $(mysql -e "SHOW FULL PROCESSLIST;" |grep unau)\nTIMESTAMP: $(date +%s)\n"; sleep .05; ((i++)); done'
            I_S: 788377361 unauthenticated user 192.168.49.162:38772 NULL Connect 1380896552 Reading from net NULL 1380896552152.118 0 0 0.000
            788377355 unauthenticated user 192.168.39.123:48828 NULL Connect 1380896552 Reading from net NULL 1380896552152.118 0 0 0.000
            SHOW: 788377355 unauthenticated user 192.168.39.123:48828 NULL Connect NULL Reading from net NULL 0.000
            788377367 unauthenticated user 192.168.38.143:56011 NULL Connect NULL Reading from net NULL 0.000
            788377368 unauthenticated user 192.168.35.174:38835 NULL Connect NULL Reading from net NULL 0.000
            TIMESTAMP: 1380896552

            I_S: 788414352 unauthenticated user connecting host NULL Connect 1380896751 login NULL 1380896751439.210 0 0 0.000
            SHOW: 788414355 unauthenticated user connecting host NULL Connect NULL login NULL 0.000
            TIMESTAMP: 1380896751

            I_S: 788490446 unauthenticated user 192.168.39.24:46534 NULL Connect 1380897163 Reading from net NULL 1380897163496.970 0 0 0.000
            SHOW: 788490447 unauthenticated user connecting host NULL Connect NULL login NULL 0.000
            TIMESTAMP: 1380897163

            I_S: 788490911 unauthenticated user 192.168.40.201:55249 NULL Connect 1380897165 Reading from net NULL 1380897165571.172 0 0 0.000
            SHOW: 788490918 unauthenticated user 192.168.48.247:55195 NULL Connect NULL Reading from net NULL 0.000
            TIMESTAMP: 1380897165{noformat}

            We can see that the Time column on I_S (as well as the Time_MS column) always reports the actual timestamp and not a duration (or a NULL value like the SHOW PROCESSLIST does) as it should.


            ps: MySQL 5.5.30 and 5.5.28 doesnt seems to have this bug (they return 0 as the Time value on I_S.PROCESSLIST for these connecting threads).
            serg Sergei Golubchik made changes -
            Assignee Elena Stepanova [ elenst ]
            elenst Elena Stepanova added a comment -

            I can easily reproduce it with a concurrent test, but haven't found an easy way to create a deterministic test case with sync points because the scenario requires a new connection where I can't set debug_sync.
            However, the reason seems to be more or less clear. Here is the patch for MDEV-4578:

            === modified file 'sql/sql_show.cc'
            — sql/sql_show.cc 2013-06-13 18:18:40 +0000
            +++ sql/sql_show.cc 2013-06-13 18:19:32 +0000
            @@ -2355,9 +2357,8 @@
            table->field[4]->store(command_name[tmp->command].str,
            command_name[tmp->command].length, cs);
            /* MYSQL_TIME */

            • const ulonglong utime= (tmp->start_time ?
            • (unow.val - tmp->start_time * HRTIME_RESOLUTION -
            • tmp->start_time_sec_part) : 0);
              + ulonglong start_utime= tmp->start_time * HRTIME_RESOLUTION + tmp->start_time_sec_part;
              + ulonglong utime= start_utime < unow.val ? unow.val - start_utime : 0;
              table->field[5]->store(utime / HRTIME_RESOLUTION, TRUE);
              /* STATE */
              if ((val= thread_state_info(tmp)))

            Earlier if tmp->start_time was 0 (which happens to be when a new connection is connecting) we would set utime to 0 as well. Now we don't check for that anymore, so utime ends up being set to unow.

            Please let me know if you need the concurrent test.

            elenst Elena Stepanova added a comment - I can easily reproduce it with a concurrent test, but haven't found an easy way to create a deterministic test case with sync points because the scenario requires a new connection where I can't set debug_sync. However, the reason seems to be more or less clear. Here is the patch for MDEV-4578 : === modified file 'sql/sql_show.cc' — sql/sql_show.cc 2013-06-13 18:18:40 +0000 +++ sql/sql_show.cc 2013-06-13 18:19:32 +0000 @@ -2355,9 +2357,8 @@ table->field [4] ->store(command_name [tmp->command] .str, command_name [tmp->command] .length, cs); /* MYSQL_TIME */ const ulonglong utime= (tmp->start_time ? (unow.val - tmp->start_time * HRTIME_RESOLUTION - tmp->start_time_sec_part) : 0); + ulonglong start_utime= tmp->start_time * HRTIME_RESOLUTION + tmp->start_time_sec_part; + ulonglong utime= start_utime < unow.val ? unow.val - start_utime : 0; table->field [5] ->store(utime / HRTIME_RESOLUTION, TRUE); /* STATE */ if ((val= thread_state_info(tmp))) Earlier if tmp->start_time was 0 (which happens to be when a new connection is connecting) we would set utime to 0 as well. Now we don't check for that anymore, so utime ends up being set to unow. Please let me know if you need the concurrent test.
            elenst Elena Stepanova made changes -
            Fix Version/s 10.0.6 [ 13202 ]
            Fix Version/s 5.5.34 [ 13700 ]
            Affects Version/s 10.0.4 [ 13101 ]
            Assignee Elena Stepanova [ elenst ] Sergei Golubchik [ serg ]
            serg Sergei Golubchik made changes -
            Status Open [ 1 ] In Progress [ 3 ]
            serg Sergei Golubchik made changes -
            Resolution Fixed [ 1 ]
            Status In Progress [ 3 ] Closed [ 6 ]
            serg Sergei Golubchik made changes -
            Workflow defaullt [ 29225 ] MariaDB v2 [ 44613 ]
            ratzpo Rasmus Johansson (Inactive) made changes -
            Workflow MariaDB v2 [ 44613 ] MariaDB v3 [ 63965 ]
            serg Sergei Golubchik made changes -
            Workflow MariaDB v3 [ 63965 ] MariaDB v4 [ 147095 ]

            People

              serg Sergei Golubchik
              jb-boin Jean Weisbuch
              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.