[MDEV-14311] wsrep.variables fails in buildbot with wrong result Created: 2017-11-07  Updated: 2020-12-08  Resolved: 2019-12-18

Status: Closed
Project: MariaDB Server
Component/s: Galera, Tests
Affects Version/s: 10.2, 10.3
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Stepan Patryshev (Inactive)
Resolution: Fixed Votes: 0
Labels: None

Sprint: 5.5.59

 Description   

http://buildbot.askmonty.org/buildbot/builders/kvm-rpm-centos6-x86/builds/5872/steps/mtr/logs/stdio

wsrep.variables                          w2 [ fail ]
 
        Test ended at 2017-11-07 14:47:54
 
 
 
CURRENT_TEST: wsrep.variables
 
--- /usr/share/mysql-test/suite/wsrep/r/variables.result	2017-11-07 13:07:43.000000000 +0200
 
+++ /dev/shm/var/2/log/variables.reject	2017-11-07 14:47:54.629938810 +0200
 
@@ -206,7 +206,7 @@
 
 Threads_connected	1
 
 SHOW STATUS LIKE 'wsrep_thread_count';
 
 Variable_name	Value
 
-wsrep_thread_count	11
 
+wsrep_thread_count	12
 
 #
 
 # MDEV#6411: Setting set @@global.wsrep_sst_auth=NULL causes crash
 
 #
 
 
 
mysqltest: Result content mismatch

Test sequence

 
worker[2] > Restart [mysqld.1 - pid: 5724, winpid: 5724] - running with different options '' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual'
 
rpl.rpl_test_framework 'stmt'            w1 [ pass ]  11705
 
worker[1] > Restart [mysqld.1 - pid: 5221, winpid: 5221] - using different config file
 
worker[1] > Restart [mysqld.2 - pid: 5223, winpid: 5223] - using different config file
 
worker[1] > Restart [mysqld.3 - pid: 5225, winpid: 5225] - using different config file
 
worker[1] > Restart [mysqld.4 - pid: 5227, winpid: 5227] - using different config file
 
worker[1] > Restart [mysqld.5 - pid: 5229, winpid: 5229] - using different config file
 
worker[1] > Restart [mysqld.6 - pid: 5234, winpid: 5234] - using different config file
 
worker[1] > Restart [mysqld.7 - pid: 5277, winpid: 5277] - using different config file
 
worker[1] > Restart [mysqld.8 - pid: 5287, winpid: 5287] - using different config file
 
worker[1] > Restart [mysqld.9 - pid: 5304, winpid: 5304] - using different config file
 
wsrep.mysql_tzinfo_to_sql_symlink        w2 [ pass ]     86
 
wsrep.plugin                             w2 [ pass ]      3
 
wsrep.mdev_6832                          w4 [ pass ]   4121
 
rpl.rpl_heartbeat_basic 'mix'            w3 [ pass ]  57381
 
worker[3] > Restart [mysqld.1 - pid: 5092, winpid: 5092] - using different config file
 
worker[3] > Restart [mysqld.2 - pid: 3295, winpid: 3295] - using different config file
 
wsrep.wsrep_rpl 'innodb,mix'             w1 [ pass ]    903
 
worker[1] > Restart [mysqld.1 - pid: 5912, winpid: 5912] - running with different options '--binlog-format=statement --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-bin=master-bin' != '--binlog-format=mixed --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-bin=master-bin'
 
worker[1] > Restart [mysqld.2 - pid: 5914, winpid: 5914] - running with different options '--binlog-format=statement --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-bin=slave-bin' != '--binlog-format=mixed --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --log-bin=slave-bin'
 
wsrep.wsrep_rpl 'innodb,row'             w3 [ pass ]    898
 
worker[3] > Restart [mysqld.1 - pid: 6016, winpid: 6016] - using different config file
 
worker[3] > Restart [mysqld.2 - pid: 6022, winpid: 6022] - using different config file
 
wsrep.mdev_7798                          w4 [ pass ]   3838
 
worker[4] > Restart [mysqld.1 - pid: 6178, winpid: 6178] - using different config file
 
wsrep.wsrep_rpl 'innodb,stmt'            w1 [ pass ]    894
 
worker[1] > Restart [mysqld.1 - pid: 6102, winpid: 6102] - using different config file
 
worker[1] > Restart [mysqld.2 - pid: 6108, winpid: 6108] - using different config file
 
maria.small_blocksize                    w1 [ pass ]     38
 
worker[1] > Restart [mysqld.1 - pid: 6248, winpid: 6248] - running with different options '--innodb-undo-tablespaces=0 --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=example_key_management.so --loose-example-key-management --aria-encrypt-tables --encrypt-tmp-disk-tables --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-rotate-key-age=15 --innodb-encryption-threads=4 --innodb-tablespaces-encryption' != '--aria-block-size=1024'
 
main.connect                             w3 [ pass ]  10176
 
worker[3] > Restart [mysqld.1 - pid: 6218, winpid: 6218] - using different config file
 
main.pool_of_threads                     w4 [ pass ]  11694
 
worker[4] > Restart [mysqld.1 - pid: 6250, winpid: 6250] - using different config file
 
encryption.innodb_encryption 'innodb,undo0' w1 [ pass ]   9508
 
worker[1] > Restart [mysqld.1 - pid: 6431, winpid: 6431] - running with different options '--auto-increment-increment=1 --loose-thread-pool-size=4' != '--innodb-undo-tablespaces=0 --innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --plugin-load-add=example_key_management.so --loose-example-key-management --aria-encrypt-tables --encrypt-tmp-disk-tables --innodb-encrypt-tables --innodb-encrypt-log --innodb-encryption-rotate-key-age=15 --innodb-encryption-threads=4 --innodb-tablespaces-encryption'
 
sys_vars.sysvars_server_embedded '32bit' w1 [ skipped ]  Test requires: embedded server
 
encryption.innodb_encryption-page-compression 'innodb' w4 [ pass ]   2415
 
sys_vars.sysvars_server_notembedded '32bit' w1 [ pass ]     43
 
worker[1] > Restart [mysqld.1 - pid: 6535, winpid: 6535] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --autocommit=0' != '--auto-increment-increment=1 --loose-thread-pool-size=4'
 
sys_vars.autocommit_func3 'innodb'       w1 [ pass ]     13
 
worker[1] > Restart [mysqld.1 - pid: 6569, winpid: 6569] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --autocommit=1' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --autocommit=0'
 
sys_vars.autocommit_func2 'innodb'       w1 [ pass ]      9
 
worker[1] > Restart [mysqld.1 - pid: 6609, winpid: 6609] - running with different options '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --autocommit=off' != '--innodb --innodb-cmpmem --innodb-cmp-per-index --innodb-trx --innodb-locks --innodb-metrics --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --innodb-sys-columns --innodb-sys-fields --innodb-sys-foreign --innodb-sys-foreign-cols --innodb-sys-indexes --innodb-sys-tables --innodb-sys-virtual --autocommit=1'
 
wsrep.variables                          w2 [ fail ]
 
        Test ended at 2017-11-07 14:47:54



 Comments   
Comment by Seppo Jaakola [ 2018-01-03 ]

To begin with, wsrep.variables test is not deterministic, it relies on a couple of sleep periods to succeed. e.g. making sleep of 3 secs shorter in this test phase:

SET GLOBAL wsrep_slave_threads= 10;
--echo # Wait for applier threads to get created.
sleep 3;
SHOW STATUS LIKE 'threads_connected';
SHOW STATUS LIKE 'wsrep_thread_count';

..., makes it possible to see this test to fail even in my laptop.

Note that changing provider or cluster address, launch long term background processes to run in the node. I suggest changing these sleeps to wait for slave thread count to settle to wanted number.

However, this particular test failure is not due to above un-deterministic behavior. The test sets applier thread count to 10, but looking at the test failure it appears that actually 11 appliers were launched. Appliers are launched one by one in: wsrep_create_appliers(long threads).

Looking at the error log, in server shutdown phase, it really confirms that 11 appliers were running during this test:

2017-11-07 14:47:50 2901072752 [Note] WSREP: applier thread exiting (code:0)
2017-11-07 14:47:50 2975525744 [Note] WSREP: recv_thread() joined.
2017-11-07 14:47:50 2975525744 [Note] WSREP: Closing replication queue.
2017-11-07 14:47:50 2975525744 [Note] WSREP: Closing slave action queue.
2017-11-07 14:47:50 2898099056 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2900769648 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2975222640 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2897795952 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2947009392 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2898402160 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2898705264 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2897492848 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2899311472 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:50 2899008368 [Note] WSREP: applier thread exiting (code:6)
2017-11-07 14:47:52 2901375856 [Note] WSREP: rollbacker thread exiting

Comment by Seppo Jaakola [ 2018-01-08 ]

This bug: https://github.com/codership/mysql-wsrep/issues/319 may be related, if not the root cause for wsrep.variables failure as well.
Fix for codership/mysql-wsrep/#319 is currently under testing. It might be good to merge in here.

Comment by Marko Mäkelä [ 2019-09-11 ]

This still fails, showing a mismatch for another thread count:

10.3 c6a6830916b08a66d0d94318e2821a608128b66d

 
wsrep.variables                          w1 [ fail ]
 
        Test ended at 2019-09-11 11:05:47
 
 
 
CURRENT_TEST: wsrep.variables
 
--- /usr/share/mysql-test/suite/wsrep/r/variables.result	2019-09-11 07:37:42.000000000 +0000
 
+++ /dev/shm/var/1/log/variables.reject	2019-09-11 11:05:47.607765929 +0000
 
@@ -195,7 +195,7 @@
 
 1
 
 SELECT VARIABLE_VALUE FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_rollbacker_thread_count';
 
 VARIABLE_VALUE
 
-1
 
+0
 
 SELECT VARIABLE_VALUE FROM INFORMATION_SCHEMA.GLOBAL_STATUS WHERE VARIABLE_NAME = 'wsrep_thread_count';
 
 VARIABLE_VALUE
 
 2
 
 
 
mysqltest: Result content mismatch

Generated at Thu Feb 08 08:12:34 UTC 2024 using Jira 8.20.16#820016-sha1:9d11dbea5f4be3d4cc21f03a88dd11d8c8687422.