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.

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.

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

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.

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;