[MDEV-5101] INFORMATION_SCHEMA.PROCESSLIST reports an incorrect value for Time for connecting threads Created: 2013-10-04  Updated: 2013-11-12  Resolved: 2013-11-12

Status: Closed
Project: MariaDB Server
Component/s: None
Affects Version/s: 10.0.4, 5.5.33a
Fix Version/s: 5.5.34, 10.0.6

Type: Bug Priority: Minor
Reporter: Jean Weisbuch Assignee: Sergei Golubchik
Resolution: Fixed Votes: 0
Labels: information_schema, processlist
Environment:

Debian Wheezy amd64
MariaDB 5.5.32 official binary (not the Debian packaged version)

Issue Links:
Relates
relates to MDEV-4578 information_schema.processlist report... Closed
relates to MDEV-4673 PROCESSLIST time in processlist is ve... Closed

 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).

 Comments   
Comment by Elena Stepanova [ 2013-10-07 ]

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.

Generated at Thu Feb 08 07:01:41 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.