Ubuntu vivid ppc64el

We are also getting this failure sporadically in buildbot.

The test uses some questionable logic to make sure that previous connections are fully disconnected, I think there is some room for improvement; but I cannot reproduce it on demand (even by running the test hundreds times), so it's difficult to experiment.

stewart-ibm,
Does it also happen if you only main.connect test separately, or otherwise is it easily reproducible for you?
If it is, would you be able to try a modified test to see if the problem is gone?

Hrrm... I haven't seen it re-occur. I'll set up a job that builds+runs tests every hour to see how reliable it is to reproduce.

I can try a modified test, sure.

If it helps, this is the tests run on the worker that failed, it could be a test ordering issue?

$ grep w7 /tmp/a
federated.federated_innodb 'old,xtradb' w7 [ pass ] 36
federated.federated_archive 'X' w7 [ pass ] 641
multi_source.multisource 'innodb_plugin' w7 [ pass ] 1713
rpl.rpl_auto_increment 'row,xtradb' w7 [ pass ] 2003
rpl.rpl_invoked_features 'mix,xtradb' w7 [ pass ] 1312
rpl.rpl_deadlock_innodb 'innodb_plugin,mix' w7 [ pass ] 37993
rpl.rpl_sp 'mix' w7 [ pass ] 1247
rpl.rpl_mdev359 'mix' w7 [ skipped ] debug_sync is not available
rpl.rpl_loaddata_s 'mix' w7 [ pass ] 1140
rpl.rpl_server_id_ignore 'mix' w7 [ pass ] 1038
rpl.rpl_start_stop_slave 'mix' w7 [ pass ] 993
rpl.rpl_drop_temp 'mix' w7 [ pass ] 1472
rpl.kill_hard-6290 'mix' w7 [ pass ] 1008
rpl.rpl_000013 'mix' w7 [ pass ] 1004
rpl.rpl_bug31076 'mix' w7 [ pass ] 232
rpl.rpl_cant_read_event_incident 'mix' w7 [ pass ] 3193
rpl.rpl_connection 'mix' w7 [ pass ] 1048
rpl.rpl_create_tmp_table_if_not_exists 'mix' w7 [ pass ] 1038
rpl.rpl_empty_master_host 'mix' w7 [ pass ] 1035
rpl.rpl_hrtime 'mix' w7 [ pass ] 1020
rpl.rpl_loadfile 'mix' w7 [ pass ] 451
rpl.rpl_mix_found_rows 'mix' w7 [ pass ] 1005
rpl.rpl_mixed_ddl_dml 'mix' w7 [ pass ] 1052
rpl.rpl_performance_schema 'mix' w7 [ pass ] 992
rpl.rpl_plugin_load 'mix' w7 [ pass ] 1021
rpl.rpl_rbr_to_sbr 'mix' w7 [ pass ] 1097
rpl.rpl_report_port 'mix' w7 [ pass ] 7751
rpl.rpl_row_unsafe_funcs 'mix' w7 [ pass ] 964
rpl.rpl_set_null_myisam 'mix' w7 [ pass ] 1229
rpl.rpl_stm_EE_err2 'mix' w7 [ pass ] 213
rpl.rpl_stm_conflicts 'mix' w7 [ pass ] 244
rpl.rpl_stm_flsh_tbls 'mix' w7 [ pass ] 350
rpl.rpl_stm_maria 'mix' w7 [ pass ] 213
rpl.rpl_stm_max_relay_size 'mix' w7 [ pass ] 1035
rpl.rpl_stm_mix_show_relaylog_events 'mix' w7 [ pass ] 1041
rpl.rpl_stm_multi_query 'mix' w7 [ pass ] 233
rpl.rpl_stm_no_op 'mix' w7 [ pass ] 211
rpl.rpl_stm_reset_slave 'mix' w7 [ pass ] 18654
rpl.rpl_stm_until 'mix' w7 [ pass ] 657
rpl.rpl_switch_stm_row_mixed 'mix' w7 [ pass ] 370
rpl.rpl_temp_table 'mix' w7 [ pass ] 237
rpl.rpl_trunc_temp 'mix' w7 [ pass ] 311
rpl.rpl_variables 'mix' w7 [ pass ] 349
rpl.rpl_variables_stm 'mix' w7 [ pass ] 307
rpl.rpl_skip_error 'row,xtradb' w7 [ pass ] 1026
rpl.rpl_extra_col_slave_myisam 'row' w7 [ pass ] 1612
rpl.rpl_row_basic_8partition 'row' w7 [ pass ] 1103
rpl.rpl_mdev359 'row' w7 [ skipped ] debug_sync is not available
rpl.semisync_memleak_4066 'row' w7 [ pass ] 994
rpl.rpl_loaddata_s 'row' w7 [ skipped ] Neither MIXED nor STATEMENT binlog format
rpl.rpl_row_annotate_dont 'row' w7 [ pass ] 1091
rpl.rpl_typeconv 'row' w7 [ pass ] 16332
rpl.rpl_bug38694 'row' w7 [ pass ] 995
rpl.rpl_replicate_do 'row' w7 [ pass ] 1008
rpl.rpl_err_ignoredtable 'row' w7 [ pass ] 997
rpl.rpl_free_items 'row' w7 [ pass ] 1169
rpl.rpl_begin_commit_rollback 'innodb_plugin,stmt' w7 [ pass ] 1199
rpl.rpl_invoked_features 'innodb_plugin,stmt' w7 [ pass ] 1235
rpl.rpl_concurrency_error 'innodb_plugin,stmt' w7 [ pass ] 10013
rpl.rpl_skip_error 'innodb_plugin,stmt' w7 [ pass ] 1028
rpl.rpl_partition_innodb 'stmt,xtradb' w7 [ pass ] 1102
rpl.rpl_stm_loaddata_concurrent 'stmt,xtradb' w7 [ pass ] 1415
rpl.rpl_mdev6020 'stmt,xtradb' w7 [ skipped ] Neither MIXED nor ROW binlog format
rpl.create_or_replace2 'stmt,xtradb' w7 [ pass ] 2972
rpl.rpl_stm_relay_ign_space 'stmt,xtradb' w7 [ pass ] 1513
rpl.rpl_binlog_grant 'stmt,xtradb' w7 [ pass ] 1177
rpl.rpl_innodb_bug30888 'stmt,xtradb' w7 [ skipped ] Neither MIXED nor ROW binlog format
rpl.rpl_loaddata 'stmt,xtradb' w7 [ pass ] 2076
rpl.rpl_mdev382 'stmt,xtradb' w7 [ pass ] 3082
rpl.rpl_set_null_innodb 'stmt,xtradb' w7 [ skipped ] Neither MIXED nor ROW binlog format
rpl.rpl_stm_binlog_max_cache_size 'stmt,xtradb' w7 [ pass ] 1492
rpl.rpl_stm_drop_create_temp_table 'stmt,xtradb' w7 [ pass ] 12029
rpl.rpl_stm_implicit_commit_binlog 'stmt,xtradb' w7 [ pass ] 1821
rpl.rpl_stm_innodb 'stmt,xtradb' w7 [ pass ] 1046
rpl.rpl_stm_start_stop_slave 'stmt,xtradb' w7 [ pass ] 10281
rpl.rpl_trigger 'stmt,xtradb' w7 [ pass ] 9802
rpl.rpl_cross_version 'stmt' w7 [ pass ] 1136
rpl.rpl_server_id2 'stmt' w7 [ pass ] 1180
rpl.rpl_relayspace 'stmt' w7 [ pass ] 1153
rpl.rpl_multi_update2 'stmt' w7 [ pass ] 1002
rpl.rpl_multi_update4 'stmt' w7 [ pass ] 994
rpl.rpl_report 'stmt' w7 [ pass ] 995
rpl.create_or_replace_row 'innodb_plugin,row' w7 [ pass ] 1432
rpl.last_insert_id 'innodb_plugin,mix' w7 [ pass ] 1005
rpl.last_insert_id 'innodb_plugin,stmt' w7 [ pass ] 999
rpl.rpl_circular_for_4_hosts 'innodb_plugin,stmt' w7 [ pass ] 1870
rpl.rpl_gtid_basic 'mix,xtradb' w7 [ pass ] 3981
rpl.rpl_gtid_master_promote 'innodb_plugin,row' w7 [ pass ] 1917
rpl.rpl_gtid_mdev4474 'innodb_plugin,mix' w7 [ pass ] 1185
rpl.rpl_gtid_mdev4485 'row' w7 [ pass ] 1043
rpl.rpl_gtid_stop_start 'innodb_plugin,row' w7 [ pass ] 22166
rpl.rpl_heartbeat_2slaves 'row' w7 [ pass ] 7933
rpl.rpl_parallel_multilevel2 'row,xtradb' w7 [ pass ] 3279
rpl.rpl_show_slave_hosts 'mix' w7 [ pass ] 6101
sys_vars.log_error_func2 w7 [ pass ] 12
main.connect w7 [ fail ]

I noticed that on the subsequent run (that passed), the ordering was very different. It was:
federated.federated_partition 'X,xtradb' w4 [ pass ] 25
multi_source.syntax 'mix' w4 [ pass ] 4863
multi_source.multisource 'xtradb' w4 [ pass ] 1743
rpl.rpl_auto_increment 'row,xtradb' w4 [ pass ] 2055
rpl.rpl_timezone 'mix' w4 [ pass ] 1049
rpl.rpl_relayrotate 'innodb_plugin,mix' w4 [ pass ] 2899
rpl.rpl_mdev6020 'mix,xtradb' w4 [ pass ] 6004
rpl.rpl_mdev6386 'mix,xtradb' w4 [ pass ] 1233
rpl.rpl_relayrotate 'mix,xtradb' w4 [ pass ] 2885
rpl.rpl_ddl 'mix,xtradb' w4 [ pass ] 1298
rpl.rpl_skip_error 'mix,xtradb' w4 [ pass ] 1046
rpl.rpl_checksum_cache 'mix,xtradb' w4 [ pass ] 6345
rpl.rpl_commit_after_flush 'mix,xtradb' w4 [ pass ] 1019
rpl.rpl_drop_db_fail 'mix,xtradb' w4 [ pass ] 776
rpl.rpl_dual_pos_advance 'mix,xtradb' w4 [ pass ] 1096
rpl.rpl_failed_optimize 'mix,xtradb' w4 [ pass ] 1012
rpl.rpl_foreign_key_innodb 'mix,xtradb' w4 [ pass ] 790
rpl.rpl_gtid_startpos 'mix,xtradb' w4 [ pass ] 3345
rpl.rpl_gtid_until 'mix,xtradb' w4 [ pass ] 2121
rpl.rpl_insert_id 'mix,xtradb' w4 [ pass ] 948
rpl.rpl_insert_id_pk 'mix,xtradb' w4 [ pass ] 1011
rpl.rpl_insert_ignore 'mix,xtradb' w4 [ pass ] 1078
rpl.rpl_multi_engine 'mix,xtradb' w4 [ pass ] 729
rpl.rpl_mysql_upgrade 'mix,xtradb' w4 [ pass ] 1330
rpl.rpl_old_master 'mix,xtradb' w4 [ pass ] 4405
rpl.rpl_read_only 'mix,xtradb' w4 [ pass ] 639
rpl.rpl_relay_space_innodb 'mix,xtradb' w4 [ pass ] 766
rpl.rpl_savepoint 'mix,xtradb' w4 [ pass ] 986
rpl.rpl_skip_replication 'mix,xtradb' w4 [ pass ] 3015
rpl.rpl_slave_grp_exec 'mix,xtradb' w4 [ pass ] 773
rpl.rpl_slave_load_in 'mix,xtradb' w4 [ pass ] 1014
rpl.rpl_temporary_error2 'mix,xtradb' w4 [ pass ] 1150
rpl.rpl_truncate_3innodb 'mix,xtradb' w4 [ pass ] 2120
rpl.rpl_invoked_features 'row,xtradb' w4 [ pass ] 1363
rpl.rpl_extra_col_slave_innodb 'innodb_plugin,row' w4 [ pass ] 4166
rpl.rpl_mdev6020 'innodb_plugin,row' w4 [ pass ] 5739
rpl.rpl_skip_error 'innodb_plugin,row' w4 [ pass ] 1082
rpl.rpl_row_loaddata_concurrent 'row,xtradb' w4 [ pass ] 2113
rpl.create_or_replace2 'row,xtradb' w4 [ pass ] 2967
rpl.rpl_temporary_errors 'row,xtradb' w4 [ pass ] 1040
rpl.rpl_row_sp003 'row,xtradb' w4 [ pass ] 987
rpl.rpl_binlog_grant 'row,xtradb' w4 [ skipped ] Neither MIXED nor STATEMENT binlog format
rpl.rpl_extra_col_master_innodb 'row,xtradb' w4 [ pass ] 3970
rpl.rpl_innodb_bug30888 'row,xtradb' w4 [ pass ] 1486
rpl.rpl_innodb_bug68220 'row,xtradb' w4 [ pass ] 1075
rpl.rpl_not_null_innodb 'row,xtradb' w4 [ pass ] 320
rpl.rpl_row_basic_3innodb 'row,xtradb' w4 [ pass ] 5005
rpl.rpl_row_binlog_max_cache_size 'row,xtradb' w4 [ pass ] 1561
rpl.rpl_row_blob_innodb 'row,xtradb' w4 [ pass ] 1062
rpl.rpl_row_create_table 'row,xtradb' w4 [ pass ] 4459
rpl.rpl_row_drop_create_temp_table 'row,xtradb' w4 [ pass ] 30468
rpl.rpl_row_func003 'row,xtradb' w4 [ pass ] 234
rpl.rpl_row_idempotency 'row,xtradb' w4 [ pass ] 480
rpl.rpl_row_implicit_commit_binlog 'row,xtradb' w4 [ pass ] 2026
rpl.rpl_row_rec_comp_innodb 'row,xtradb' w4 [ pass ] 3433
rpl.rpl_row_sp002_innodb 'row,xtradb' w4 [ pass ] 880
rpl.rpl_row_sp006_InnoDB 'row,xtradb' w4 [ pass ] 798
rpl.rpl_row_sp007_innodb 'row,xtradb' w4 [ pass ] 771
rpl.rpl_row_tabledefs_3innodb 'row,xtradb' w4 [ pass ] 1077
rpl.rpl_row_tbl_metadata 'row,xtradb' w4 [ pass ] 2358
rpl.rpl_row_trig004 'row,xtradb' w4 [ pass ] 1113
rpl.rpl_row_triggers 'row,xtradb' w4 [ skipped ] RBR triggers are not available
rpl.rpl_set_null_innodb 'row,xtradb' w4 [ pass ] 1977
rpl.rpl_stm_innodb 'row,xtradb' w4 [ skipped ] Neither MIXED nor STATEMENT binlog format
rpl.rpl_trigger 'row,xtradb' w4 [ skipped ] Neither MIXED nor STATEMENT binlog format
rpl.rpl_typeconv_innodb 'row,xtradb' w4 [ pass ] 969
rpl.rpl_semi_sync_event 'innodb_plugin,stmt' w4 [ pass ] 21133
rpl.create_or_replace2 'stmt,xtradb' w4 [ pass ] 2964
rpl.rpl_stm_relay_ign_space 'stmt,xtradb' w4 [ pass ] 1423
rpl.rpl_binlog_grant 'stmt,xtradb' w4 [ pass ] 1204
rpl.rpl_innodb_bug30888 'stmt,xtradb' w4 [ skipped ] Neither MIXED nor ROW binlog format
rpl.rpl_loaddata 'stmt,xtradb' w4 [ pass ] 2053
rpl.rpl_mdev382 'stmt,xtradb' w4 [ pass ] 3076
rpl.rpl_set_null_innodb 'stmt,xtradb' w4 [ skipped ] Neither MIXED nor ROW binlog format
rpl.rpl_stm_binlog_max_cache_size 'stmt,xtradb' w4 [ pass ] 1524
rpl.rpl_stm_drop_create_temp_table 'stmt,xtradb' w4 [ pass ] 38622
rpl.rpl_stm_implicit_commit_binlog 'stmt,xtradb' w4 [ pass ] 1516
rpl.rpl_stm_innodb 'stmt,xtradb' w4 [ pass ] 1033
rpl.rpl_stm_start_stop_slave 'stmt,xtradb' w4 [ pass ] 10234
rpl.rpl_trigger 'stmt,xtradb' w4 [ pass ] 9752
rpl.create_or_replace_row 'innodb_plugin,row' w4 [ pass ] 1448
rpl.last_insert_id 'mix,xtradb' w4 [ pass ] 999
rpl.last_insert_id 'innodb_plugin,stmt' w4 [ pass ] 1122
rpl.rpl_circular_for_4_hosts 'innodb_plugin,stmt' w4 [ pass ] 1811
rpl.rpl_gtid_basic 'innodb_plugin,row' w4 [ pass ] 3983
rpl.rpl_gtid_master_promote 'mix,xtradb' w4 [ pass ] 3315
rpl.rpl_gtid_mdev4473 'mix,xtradb' w4 [ pass ] 1273
rpl.rpl_gtid_mdev4485 'row' w4 [ pass ] 3238
rpl.rpl_gtid_stop_start 'innodb_plugin,mix' w4 [ pass ] 25304
rpl.rpl_heartbeat_2slaves 'stmt' w4 [ pass ] 7967
rpl.rpl_parallel_multilevel2 'innodb_plugin,stmt' w4 [ pass ] 7334
sys_vars.log_error_func w4 [ pass ] 23
sys_vars.log_error_func2 w4 [ pass ] 5
sys_vars.slave_parallel_threads_basic w4 [ pass ] 13
main.connect w4 [ pass ] 10464

Thanks, but no, it does not really help. The test has non-default startup options, so the server gets restarted before running it anyway. You can't see it in your log, but if you run MTR with --verbose-restart, you will.

My current suspicion is that the test hits a race condition. What it does in this fragment is disconnect extra connections, check that they disappeared from the process list, then run FLUSH STATUS and make sure that Max_used_connections is set to 1. I suppose it might happen that a connection has already disappeared from the process list, but the status variables have not been updated yet. To check this theory, I would call the pair of include files count_sessions.inc / wait_until_count_sessions.inc which we normally use to make sure that connections are really gone. They use Threads_connected status variable to verify it, so hopefully the race condition will be avoided.

However, I need to be able to reproduce it in order to verify. I can probably trigger it artificially by adding a delay in a proper place in the code (assuming the theory has merits and there is such a place), but I'm afraid if the cause of the failure is actually different, I will be solving an imaginary issue instead of the real one. I will do it anyway if we don't find a machine/system/build where it is reasonably reproducible.

From a quick look at the code (albeit MySQL 5.7 code), it looks like that they indeed do not get updated in any way atomically, so the race very likely exists.

Yes, with this I'm getting the problem reliably:

elenst@wheezy-64:~/git/10.0-bug$ git diff

diff --git a/sql/mysqld.cc b/sql/mysqld.cc

index 6f28244..56480ea 100644

--- a/sql/mysqld.cc

+++ b/sql/mysqld.cc

@@ -2770,6 +2770,7 @@ void unlink_thd(THD *thd)

   mysql_mutex_unlock(&LOCK_thread_count);

   delete thd;

+  DBUG_EXECUTE_IF("sleep_before_thd_count_decrement", sleep(1););

   thread_safe_decrement32(&thread_count, &thread_count_lock);

   DBUG_VOID_RETURN;

$ perl ./mtr main.connect --mysqld=--debug_dbug='+d,sleep_before_thd_count_decrement'

main.connect                             [ fail ]

        Test ended at 2015-07-14 21:04:09

CURRENT_TEST: main.connect

--- /data/repo/git/10.0-bug/mysql-test/r/connect.result	2015-05-03 00:51:21.000000000 +0300

+++ /data/repo/git/10.0-bug/mysql-test/r/connect.reject	2015-07-14 21:04:07.000000000 +0300

@@ -215,7 +215,7 @@

 SHOW STATUS LIKE 'max_used_connections';

 Variable_name	Value

-Max_used_connections	1

+Max_used_connections	5

 # -- Starting Event Scheduler...

 SET GLOBAL event_scheduler = ON;

@@ -226,7 +226,7 @@

 # -- Check that max_used_connections hasn't changed.

 SHOW STATUS LIKE 'max_used_connections';

 Variable_name	Value

-Max_used_connections	2

+Max_used_connections	5

 # -- Closing new connection...

mysqltest: Result content mismatch

So, the race condition is between FLUSH STATUS and updating thread_count. The latter is not directly exposed externally as far as i can see, so synchronization on the test level is a bit tricky.
The problem can be avoided, for example, this way:

diff --git a/mysql-test/r/connect.result b/mysql-test/r/connect.result

index 32c7bdf..0598d7c 100644

--- a/mysql-test/r/connect.result

+++ b/mysql-test/r/connect.result

@@ -211,8 +211,6 @@ DROP USER mysqltest_u1@localhost;

 # -- Bug#35074: max_used_connections is not correct.

-FLUSH STATUS;

-

 SHOW STATUS LIKE 'max_used_connections';

 Variable_name  Value

 Max_used_connections   1

diff --git a/mysql-test/t/connect.test b/mysql-test/t/connect.test

index fca588d..7042983 100644

--- a/mysql-test/t/connect.test

+++ b/mysql-test/t/connect.test

@@ -253,9 +253,28 @@ DROP USER mysqltest_u1@localhost;

 --echo # -- Bug#35074: max_used_connections is not correct.

 --echo

-FLUSH STATUS;

+--disable_query_log

---echo

+--let $wait_timeout= 10

+while ($wait_timeout) 

+{

+  --dec $wait_timeout

+  FLUSH STATUS;

+  --let $val= query_get_value(SHOW GLOBAL STATUS LIKE 'Max_used_connections', Value, 1)

+  if ($val == 1)

+  {

+    --let $wait_timeout= 0

+  }

+  --sleep 1

+}

+--enable_query_log

+

+if ($val != 1)

+{

+  SHOW GLOBAL STATUS LIKE 'Max_used_connections';

+  --die "Max used connections value was not reset to 1 as it was supposed to"

+}

+       

 SHOW STATUS LIKE 'max_used_connections';

 --echo

But I would like to get a confirmation from serg before pushing it, because I find the test and bugfix for bug#35074 rather confusing.
Here is the patch: http://lists.mysql.com/commits/43902
What it attempted to fix (and check in the test) is that service threads like event_scheduler's do not affect Max_used_connections value.

However, it only changes Max_used_connections calculation upon creating a new thread, while in refresh_status it's still the same:

max_used_connections= thread_count-delayed_insert_threads;

So, after FLUSH STATUS Max_used_connections counts service threads as well.

connect  con1,localhost,root,,;

disconnect con1;

connection default;

SHOW GLOBAL STATUS LIKE 'Max_used_connections';

Variable_name	Value

Max_used_connections	2

SET GLOBAL event_scheduler = ON;

SHOW GLOBAL STATUS LIKE 'Max_used_connections';

Variable_name	Value

Max_used_connections	2

FLUSH STATUS;

SHOW GLOBAL STATUS LIKE 'Max_used_connections';

Variable_name	Value

Max_used_connections	2

But then again, there is a comment in refresh_status:

  /*

    Set max_used_connections to the number of currently open

    connections.  Lock LOCK_thread_count out of LOCK_status to avoid

    deadlocks.  Status reset becomes not atomic, but status data is

    not exact anyway.

  */

So, maybe the discrepancy is anticipated.

For what it's worth, it appears to be fixed in 5.7.