[MDEV-6656] Test wsrep.variables hangs - JIRA

Details

Type: Bug
Status: Closed
Priority: Major
Resolution: Fixed
Affects Version/s: 10.0.12-galera
Fix Version/s: 10.0.13-galera
Component/s: None
Labels:
None
Environment:
Linux Mint 17,uname -a
Linux jan-GE70-0NC-0ND 3.13.0-29-generic #53-Ubuntu SMP Wed Jun 4 21:00:20 UTC 2014 x86_64 x86_64 x86_64 GNU/Linux,
gcc --version
gcc (Ubuntu 4.8.2-19ubuntu1) 4.8.2

Description

Test case hangs maybe not every time but very often.

Using debug build, I run test case with following:

jan@jan-GE70-0NC-0ND ~/mysql/10.0-galera/mysql-test $ ./mysql-test-run --vardir=/dev/shm wsrep.variables --ddd --mysqld=--wsrep-debug=1
Logging: ./mysql-test-run  --vardir=/dev/shm wsrep.variables --ddd --mysqld=--wsrep-debug=1
vardir: /run/shm
Checking leftover processes...
Removing old var directory...
couldn't chmod(0777, /run/shm/sem.ADBE_REL_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_REL_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm/sem.ADBE_WritePrefs_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_WritePrefs_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm/sem.ADBE_ReadPrefs_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_ReadPrefs_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 853.
Couldn't remove directory '/run/shm': Permission denied at /usr/share/perl/5.18/File/Find.pm line 853.
Creating var directory '/run/shm'...
Checking supported features...
MariaDB Version 10.0.12-MariaDB-wsrep-debug
 - SSL connections supported
 - binaries are debug compiled
 - binaries built with wsrep patch
 - adding wsrep, galera to default test suites
Collecting tests...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019
^Cmysql-test-run: *** ERROR: Got ^C signal
jan@jan-GE70-0NC-0ND ~/mysql/10.0-galera/mysql-test $ killall -9 mysqld
jan@jan-GE70-0NC-0ND ~/mysql/10.0-galera/mysql-test $ ./mysql-test-run --vardir=/dev/shm wsrep.variables --ddd --mysqld=--wsrep-debug=1
Logging: ./mysql-test-run  --vardir=/dev/shm wsrep.variables --ddd --mysqld=--wsrep-debug=1
vardir: /run/shm
Checking leftover processes...
Removing old var directory...
couldn't chmod(0777, /run/shm/sem.ADBE_REL_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_REL_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm/sem.ADBE_WritePrefs_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_WritePrefs_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm/sem.ADBE_ReadPrefs_mdm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
Couldn't delete file '/run/shm/sem.ADBE_ReadPrefs_mdm': Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 796.
couldn't chmod(0777, /run/shm): Operation not permitted at /usr/share/perl/5.18/File/Find.pm line 853.
Couldn't remove directory '/run/shm': Permission denied at /usr/share/perl/5.18/File/Find.pm line 853.
Creating var directory '/run/shm'...
Checking supported features...
MariaDB Version 10.0.12-MariaDB-wsrep-debug
 - SSL connections supported
 - binaries are debug compiled
 - binaries built with wsrep patch
 - adding wsrep, galera to default test suites
Collecting tests...
Installing system database...

==============================================================================

TEST                                      RESULT   TIME (ms) or COMMENT
--------------------------------------------------------------------------

worker[1] Using MTR_BUILD_THREAD 300, with reserved ports 16000..16019

And ddd output

GNU DDD 3.3.12 (x86_64-pc-linux-gnu), by Dorothea Lütkehaus and Andreas Zeller.
Copyright © 1995-1999 Technische Universität Braunschweig, Germany.
Copyright © 1999-2001 Universität Passau, Germany.
Copyright © 2001 Universität des Saarlandes, Germany.
Copyright © 2001-2004 Free Software Foundation, Inc.
Reading symbols from /home/jan/mysql/10.0-galera/sql/mysqld...done.
(gdb) run
Starting program: /home/jan/mysql/10.0-galera/sql/mysqld --defaults-group-suffix=.1 --defaults-file=/run/shm/my.cnf --log-output=file --gdb --wsrep-debug=1 --core-file --loose-debug-sync-timeout=300 
[Thread debugging using libthread_db enabled]
Using host libthread_db library "/lib/x86_64-linux-gnu/libthread_db.so.1".
[New Thread 0x7ffff5bff700 (LWP 20091)]
[Thread 0x7ffff5bff700 (LWP 20091) exited]
[New Thread 0x7ffff5bff700 (LWP 20092)]
140828 15:18:55 [Note] Plugin 'InnoDB' is disabled.
140828 15:18:55 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
140828 15:18:55 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
140828 15:18:55 [Note] Plugin 'XTRADB_RSEG' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_TRX' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_CMPMEM' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_BUFFER_PAGE' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_BUFFER_PAGE_LRU' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_BUFFER_POOL_STATS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_METRICS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_TABLES' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_FOREIGN' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_FOREIGN_COLS' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
140828 15:18:55 [Note] Plugin 'INNODB_CHANGED_PAGES' is disabled.
140828 15:18:55 [Note] Plugin 'partition' is disabled.
140828 15:18:55 [Warning] /home/jan/mysql/10.0-galera/sql/mysqld: unknown variable 'loose-feedback-user-info=mysql-test'
140828 15:18:55 [Note] WSREP: Initial TC log open: dummy
140828 15:18:55 [Note] Server socket created on IP: '0.0.0.0'.
[New Thread 0x7ffff7fc4700 (LWP 20093)]
140828 15:18:55 [Note] Event Scheduler: Loaded 0 events
140828 15:18:55 [Note] WSREP: Setting wsrep_ready to 0
140828 15:18:55 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:18:55 [Note] WSREP: wsrep_load(): loading provider library 'none'
140828 15:18:55 [Note] WSREP: Setting wsrep_ready to 1
140828 15:18:55 [Note] [Debug] WSREP: dummy_init
[New Thread 0x7ffff7f7b700 (LWP 20097)]
140828 15:18:55 [Note] /home/jan/mysql/10.0-galera/sql/mysqld: ready for connections.
Version: '10.0.12-MariaDB-wsrep-debug-log'  socket: '/run/shm/tmp/mysqld.1.sock'  port: 16000  Source distribution, wsrep_25.10.r4002
[Thread 0x7ffff7f7b700 (LWP 20097) exited]
[New Thread 0x7ffff7f7b700 (LWP 20098)]
140828 15:18:55 [Note] [Debug] WSREP: dummy_stats_get
140828 15:18:55 [Note] [Debug] WSREP: dummy_stats_free
[Thread 0x7ffff7f7b700 (LWP 20098) exited]
[New Thread 0x7ffff7f7b700 (LWP 20102)]
140828 15:18:55 [Note] WSREP: wsrep_provider_update: /usr/lib/galera/libgalera_smm.so
140828 15:18:55 [Note] WSREP: Stop replication
140828 15:18:55 [Note] WSREP: Provider disconnect
140828 15:18:55 [Note] [Debug] WSREP: dummy_disconnect
140828 15:18:57 [Note] WSREP: waiting for client connections to close: 1
140828 15:18:57 [Note] [Debug] WSREP: dummy_free
140828 15:18:57 [Note] WSREP: Setting wsrep_ready to 0
140828 15:18:57 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:18:57 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
140828 15:18:57 [Note] WSREP: wsrep_load(): Galera 3.5(rXXXX) by Codership Oy <info@codership.com> loaded successfully.
140828 15:18:57 [Note] WSREP: CRC-32C: using hardware acceleration.
140828 15:18:57 [Warning] WSREP: Could not open saved state file for reading: /run/shm/mysqld.1/data//grastate.dat
140828 15:18:57 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
140828 15:18:57 [Note] WSREP: Passing config to GCS: base_host = 178.251.60.217; base_port = 4567; cert.log_conflicts = no; debug = no; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 1; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /run/shm/mysqld.1/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /run/shm/mysqld.1/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.version = 0; pc.wait_prim = true; pc.wait_prim_timeout = P30S; pc.w
[New Thread 0x7fffe53f0700 (LWP 20109)]
140828 15:18:58 [Note] WSREP: Service thread queue flushed.
140828 15:18:58 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
140828 15:18:58 [Note] WSREP: wsrep_cluster_address_init:  -> null
140828 15:18:58 [Note] WSREP: refresh_provider_options: null
140828 15:18:58 [Note] WSREP: wsrep_provider_update: none
140828 15:18:58 [Note] WSREP: Stop replication
140828 15:18:58 [Note] WSREP: Provider disconnect
140828 15:19:00 [Note] WSREP: waiting for client connections to close: 1
140828 15:19:00 [Note] WSREP: dtor state: CLOSED
140828 15:19:00 [Note] WSREP: apply mon: entered 0
140828 15:19:00 [Note] WSREP: apply mon: entered 0
140828 15:19:00 [Note] WSREP: apply mon: entered 0
140828 15:19:00 [Note] WSREP: cert index usage at exit 0
140828 15:19:00 [Note] WSREP: cert trx map usage at exit 0
140828 15:19:00 [Note] WSREP: deps set usage at exit 0
140828 15:19:00 [Note] WSREP: avg deps dist 0
140828 15:19:00 [Note] WSREP: avg cert interval 0
140828 15:19:00 [Note] WSREP: cert index size 0
140828 15:19:00 [Note] WSREP: Service thread queue flushed.
140828 15:19:00 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0
[Thread 0x7fffe53f0700 (LWP 20109) exited]
140828 15:19:00 [Note] WSREP: Flushing memory map to disk...
140828 15:19:00 [Note] WSREP: Setting wsrep_ready to 0
140828 15:19:00 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:19:00 [Note] WSREP: wsrep_load(): loading provider library 'none'
140828 15:19:00 [Note] WSREP: Setting wsrep_ready to 1
140828 15:19:00 [Note] [Debug] WSREP: dummy_init
140828 15:19:00 [Note] WSREP: wsrep_cluster_address_init: null -> null
140828 15:19:00 [Note] WSREP: refresh_provider_options: null
140828 15:19:00 [Note] [Debug] WSREP: dummy_options_get
140828 15:19:00 [Note] WSREP: wsrep_provider_update: /usr/lib/galera/libgalera_smm.so
140828 15:19:00 [Note] WSREP: Stop replication
140828 15:19:00 [Note] WSREP: Provider disconnect
140828 15:19:00 [Note] [Debug] WSREP: dummy_disconnect
140828 15:19:02 [Note] WSREP: waiting for client connections to close: 1
140828 15:19:02 [Note] [Debug] WSREP: dummy_free
140828 15:19:02 [Note] WSREP: Setting wsrep_ready to 0
140828 15:19:02 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:19:02 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
140828 15:19:02 [Note] WSREP: wsrep_load(): Galera 3.5(rXXXX) by Codership Oy <info@codership.com> loaded successfully.
140828 15:19:02 [Note] WSREP: CRC-32C: using hardware acceleration.
140828 15:19:02 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
140828 15:19:02 [Note] WSREP: Passing config to GCS: base_host = 178.251.60.217; base_port = 4567; cert.log_conflicts = no; debug = no; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 1; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /run/shm/mysqld.1/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /run/shm/mysqld.1/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; ist.recv_addr = 178.251.60.217; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.version = 0; pc.wait_prim = true; p
[New Thread 0x7fffe53f0700 (LWP 20117)]
140828 15:19:02 [Note] WSREP: Service thread queue flushed.
140828 15:19:02 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
140828 15:19:02 [Note] WSREP: wsrep_cluster_address_init: null -> null
140828 15:19:02 [Note] WSREP: refresh_provider_options: null
140828 15:19:02 [Note] WSREP: wsrep_provider_update: none
140828 15:19:02 [Note] WSREP: Stop replication
140828 15:19:02 [Note] WSREP: Provider disconnect
140828 15:19:04 [Note] WSREP: waiting for client connections to close: 1
140828 15:19:04 [Note] WSREP: dtor state: CLOSED
140828 15:19:04 [Note] WSREP: apply mon: entered 0
140828 15:19:04 [Note] WSREP: apply mon: entered 0
140828 15:19:04 [Note] WSREP: apply mon: entered 0
140828 15:19:04 [Note] WSREP: cert index usage at exit 0
140828 15:19:04 [Note] WSREP: cert trx map usage at exit 0
140828 15:19:04 [Note] WSREP: deps set usage at exit 0
140828 15:19:04 [Note] WSREP: avg deps dist 0
140828 15:19:04 [Note] WSREP: avg cert interval 0
140828 15:19:04 [Note] WSREP: cert index size 0
140828 15:19:04 [Note] WSREP: Service thread queue flushed.
140828 15:19:04 [Note] WSREP: wsdb trx map usage 0 conn query map usage 0
[Thread 0x7fffe53f0700 (LWP 20117) exited]
140828 15:19:04 [Note] WSREP: Flushing memory map to disk...
140828 15:19:04 [Note] WSREP: Setting wsrep_ready to 0
140828 15:19:04 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:19:04 [Note] WSREP: wsrep_load(): loading provider library 'none'
140828 15:19:04 [Note] WSREP: Setting wsrep_ready to 1
140828 15:19:04 [Note] [Debug] WSREP: dummy_init
140828 15:19:04 [Note] WSREP: wsrep_cluster_address_init: null -> null
140828 15:19:04 [Note] WSREP: refresh_provider_options: null
140828 15:19:04 [Note] [Debug] WSREP: dummy_options_get
140828 15:19:04 [Note] [Debug] WSREP: dummy_stats_get
140828 15:19:04 [Note] [Debug] WSREP: dummy_stats_free
140828 15:19:04 [Note] [Debug] WSREP: dummy_stats_get
140828 15:19:04 [Note] [Debug] WSREP: dummy_stats_free
140828 15:19:04 [Note] WSREP: wsrep_provider_update: /usr/lib/galera/libgalera_smm.so
140828 15:19:04 [Note] WSREP: Stop replication
140828 15:19:04 [Note] WSREP: Provider disconnect
140828 15:19:04 [Note] [Debug] WSREP: dummy_disconnect
140828 15:19:06 [Note] WSREP: waiting for client connections to close: 1
140828 15:19:06 [Note] [Debug] WSREP: dummy_free
140828 15:19:06 [Note] WSREP: Setting wsrep_ready to 0
140828 15:19:06 [Note] WSREP: Read nil XID from storage engines, skipping position init
140828 15:19:06 [Note] WSREP: wsrep_load(): loading provider library '/usr/lib/galera/libgalera_smm.so'
140828 15:19:06 [Note] WSREP: wsrep_load(): Galera 3.5(rXXXX) by Codership Oy <info@codership.com> loaded successfully.
140828 15:19:06 [Note] WSREP: CRC-32C: using hardware acceleration.
140828 15:19:06 [Note] WSREP: Found saved state: 00000000-0000-0000-0000-000000000000:-1
140828 15:19:06 [Note] WSREP: Passing config to GCS: base_host = 178.251.60.217; base_port = 4567; cert.log_conflicts = no; debug = no; evs.inactive_check_period = PT0.5S; evs.inactive_timeout = PT15S; evs.join_retrans_period = PT1S; evs.max_install_timeouts = 1; evs.send_window = 4; evs.stats_report_period = PT1M; evs.suspect_timeout = PT5S; evs.user_send_window = 2; evs.view_forget_timeout = PT24H; gcache.dir = /run/shm/mysqld.1/data/; gcache.keep_pages_size = 0; gcache.mem_size = 0; gcache.name = /run/shm/mysqld.1/data//galera.cache; gcache.page_size = 128M; gcache.size = 128M; gcs.fc_debug = 0; gcs.fc_factor = 1.0; gcs.fc_limit = 16; gcs.fc_master_slave = no; gcs.max_packet_size = 64500; gcs.max_throttle = 0.25; gcs.recv_q_hard_limit = 9223372036854775807; gcs.recv_q_soft_limit = 0.25; gcs.sync_donor = no; gmcast.segment = 0; gmcast.version = 0; ist.recv_addr = 178.251.60.217; pc.announce_timeout = PT3S; pc.checksum = false; pc.ignore_quorum = false; pc.ignore_sb = false; pc.npvo = false; pc.version = 0; pc.wait_prim = true; p
[New Thread 0x7fffe53f0700 (LWP 20124)]
140828 15:19:06 [Note] WSREP: Service thread queue flushed.
140828 15:19:06 [Note] WSREP: Assign initial position for certification: -1, protocol version: -1
140828 15:19:06 [Note] WSREP: wsrep_cluster_address_init: null -> null
140828 15:19:06 [Note] WSREP: refresh_provider_options: null
140828 15:19:06 [Note] WSREP: Stop replication
140828 15:19:06 [Note] WSREP: Provider disconnect
140828 15:19:08 [Note] WSREP: waiting for client connections to close: 1
safe_mutex: Found wrong usage of mutex 'LOCK_wsrep_slave_threads' and 'LOCK_global_system_variables'
Mutex currently locked (in reverse order):
LOCK_global_system_variables      /home/jan/mysql/10.0-galera/sql/wsrep_var.cc  line 343
LOCK_wsrep_slave_threads          /home/jan/mysql/10.0-galera/sql/sys_vars_shared.h  line 55
140828 15:19:08 [Note] WSREP: Start replication
140828 15:19:08 [Note] WSREP: Setting initial position to 00000000-0000-0000-0000-000000000000:-1
140828 15:19:08 [Note] WSREP: protonet asio version 0
140828 15:19:08 [Note] WSREP: Using CRC-32C (optimized) for message checksums.
140828 15:19:08 [Note] WSREP: backend: asio
140828 15:19:08 [Note] WSREP: GMCast version 0
140828 15:19:08 [Note] WSREP: (8286b8c5-2ead-11e4-a515-fa3203f0f2b7, 'tcp://0.0.0.0:4567') listening at tcp://0.0.0.0:4567
140828 15:19:08 [Note] WSREP: (8286b8c5-2ead-11e4-a515-fa3203f0f2b7, 'tcp://0.0.0.0:4567') multicast: , ttl: 1
140828 15:19:08 [Note] WSREP: EVS version 0
140828 15:19:08 [Note] WSREP: PC version 0
140828 15:19:08 [Note] WSREP: gcomm: connecting to group 'my_wsrep_cluster', peer ''
140828 15:19:08 [Note] WSREP: Node 8286b8c5-2ead-11e4-a515-fa3203f0f2b7 state prim
140828 15:19:08 [Note] WSREP: view(view_id(PRIM,8286b8c5-2ead-11e4-a515-fa3203f0f2b7,1) memb {
	8286b8c5-2ead-11e4-a515-fa3203f0f2b7,0
} joined {
} left {
} partitioned {
})
[New Thread 0x7fffe27ff700 (LWP 20125)]
140828 15:19:08 [Note] WSREP: gcomm: connected
140828 15:19:08 [Note] WSREP: Changing maximum packet size to 64500, resulting msg size: 32636
[New Thread 0x7fffe17ff700 (LWP 20126)]
140828 15:19:08 [Note] WSREP: Shifting CLOSED -> OPEN (TO: 0)
140828 15:19:08 [Note] WSREP: Opened channel 'my_wsrep_cluster'
140828 15:19:08 [Note] WSREP: New COMPONENT: primary = yes, bootstrap = no, my_idx = 0, memb_num = 1
[New Thread 0x7ffff7f32700 (LWP 20127)]
[New Thread 0x7ffff7ee9700 (LWP 20128)]
140828 15:19:08 [Note] WSREP: Starting new group from scratch: 829129a0-2ead-11e4-be1f-0b20a4cabe2f
140828 15:19:08 [Note] WSREP: STATE_EXCHANGE: sent state UUID: 82913900-2ead-11e4-9ce8-5358a4a82b69
140828 15:19:08 [Note] WSREP: STATE EXCHANGE: sent state msg: 82913900-2ead-11e4-9ce8-5358a4a82b69
140828 15:19:08 [Note] WSREP: STATE EXCHANGE: got state msg: 82913900-2ead-11e4-9ce8-5358a4a82b69 from 0 (jan-GE70-0NC-0ND)
140828 15:19:08 [Note] WSREP: Quorum results:
	version    = 3,
	component  = PRIMARY,
	conf_id    = 0,
	members    = 1/1 (joined/total),
	act_id     = 0,
	last_appl. = -1,
	protocols  = 0/5/3 (gcs/repl/appl),
	group UUID = 829129a0-2ead-11e4-be1f-0b20a4cabe2f
140828 15:19:08 [Note] WSREP: Flow-control interval: [16, 16]
140828 15:19:08 [Note] WSREP: Restored state OPEN -> JOINED (0)
140828 15:19:08 [Note] WSREP: Member 0.0 (jan-GE70-0NC-0ND) synced with group.
140828 15:19:08 [Note] WSREP: Shifting JOINED -> SYNCED (TO: 0)
140828 15:19:08 [Note] WSREP: New cluster view: global state: 829129a0-2ead-11e4-be1f-0b20a4cabe2f:0, view# 1: Primary, number of nodes: 1, my index: 0, protocol version 3
140828 15:19:08 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140828 15:19:08 [Note] WSREP: REPL Protocols: 5 (3, 1)
140828 15:19:08 [Note] WSREP: Service thread queue flushed.
140828 15:19:08 [Note] WSREP: Assign initial position for certification: 0, protocol version: 3
140828 15:19:08 [Note] WSREP: Service thread queue flushed.
140828 15:19:08 [Note] WSREP: Synchronized with group, ready for connections
140828 15:19:08 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140828 15:19:08 [Note] WSREP: Nobody is waiting for SST.
[New Thread 0x7ffff7ea0700 (LWP 20129)]
[New Thread 0x7ffff7e57700 (LWP 20130)]
[New Thread 0x7ffff6575700 (LWP 20131)]
[New Thread 0x7ffff652c700 (LWP 20132)]
[New Thread 0x7ffff64e3700 (LWP 20133)]
[New Thread 0x7ffff649a700 (LWP 20134)]
[New Thread 0x7ffff6451700 (LWP 20135)]
[New Thread 0x7ffff51a0700 (LWP 20136)]
[New Thread 0x7ffff5157700 (LWP 20137)]
140828 15:19:14 [Note] WSREP: wsrep_provider_update: none
140828 15:19:14 [Note] WSREP: Stop replication
140828 15:19:14 [Note] WSREP: Provider disconnect
140828 15:19:14 [Note] WSREP: Closing send monitor...
140828 15:19:14 [Note] WSREP: Closed send monitor.
140828 15:19:14 [Note] WSREP: gcomm: terminating thread
140828 15:19:14 [Note] WSREP: gcomm: joining thread
140828 15:19:14 [Note] WSREP: gcomm: closing backend
[Thread 0x7fffe27ff700 (LWP 20125) exited]
140828 15:19:14 [Note] WSREP: view((empty))
140828 15:19:14 [Note] WSREP: Received self-leave message.
140828 15:19:14 [Note] WSREP: gcomm: closed
140828 15:19:14 [Note] WSREP: Flow-control interval: [0, 0]
140828 15:19:14 [Note] WSREP: Received SELF-LEAVE. Closing connection.
140828 15:19:14 [Note] WSREP: Shifting SYNCED -> CLOSED (TO: 0)
140828 15:19:14 [Note] WSREP: RECV thread exiting 0: Success
140828 15:19:14 [Note] WSREP: New cluster view: global state: 829129a0-2ead-11e4-be1f-0b20a4cabe2f:0, view# -1: non-Primary, number of nodes: 0, my index: -1, protocol version 3
140828 15:19:14 [Note] WSREP: Setting wsrep_ready to 0
140828 15:19:14 [Note] WSREP: wsrep_notify_cmd is not defined, skipping notification.
140828 15:19:14 [Note] WSREP: applier thread exiting (code:0)
140828 15:19:14 [Note] WSREP: closing applier 12
140828 15:19:14 [Note] WSREP: wsrep running threads now: 10
[Thread 0x7fffe17ff700 (LWP 20126) exited]
140828 15:19:14 [Note] WSREP: recv_thread() joined.
140828 15:19:14 [Note] WSREP: Closing replication queue.
140828 15:19:14 [Note] WSREP: Closing slave action queue.
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: closing applier 9
[Thread 0x7ffff6451700 (LWP 20135) exited]
140828 15:19:14 [Note] WSREP: wsrep running threads now: 9
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: closing applier 14
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
[Thread 0x7ffff64e3700 (LWP 20133) exited]
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: applier thread exiting (code:6)
140828 15:19:14 [Note] WSREP: closing applier 6
140828 15:19:14 [Note] WSREP: closing applier 7
140828 15:19:14 [Note] WSREP: wsrep running threads now: 8
140828 15:19:14 [Note] WSREP: wsrep running threads now: 7
140828 15:19:14 [Note] WSREP: closing applier 8
140828 15:19:14 [Note] WSREP: closing applier 5
140828 15:19:14 [Note] WSREP: wsrep running threads now: 6
140828 15:19:14 [Note] WSREP: wsrep running threads now: 5
140828 15:19:14 [Note] WSREP: wsrep running threads now: 4
140828 15:19:14 [Note] WSREP: closing applier 13
140828 15:19:14 [Note] WSREP: closing applier 10
[Thread 0x7ffff652c700 (LWP 20132) exited]
140828 15:19:14 [Note] WSREP: closing applier 11
140828 15:19:14 [Note] WSREP: wsrep running threads now: 3
140828 15:19:14 [Note] WSREP: wsrep running threads now: 2
140828 15:19:14 [Note] WSREP: wsrep running threads now: 1
[Thread 0x7ffff51a0700 (LWP 20136) exited]
[Thread 0x7ffff5157700 (LWP 20137) exited]
[Thread 0x7ffff7ea0700 (LWP 20129) exited]
[Thread 0x7ffff7e57700 (LWP 20130) exited]
[Thread 0x7ffff649a700 (LWP 20134) exited]
[Thread 0x7ffff6575700 (LWP 20131) exited]
[Thread 0x7ffff7ee9700 (LWP 20128) exited]
140828 15:19:16 [Note] WSREP: waiting for client connections to close: 2
140828 15:19:16 [Note] WSREP: closing wsrep thread 4
140828 15:19:16 [Note] WSREP: WSREP rollback thread wakes for signal
140828 15:19:16 [Note] WSREP: WSREP rollback thread has empty abort queue
140828 15:19:16 [Note] WSREP: rollbacker thread exiting
140828 15:19:16 [Note] WSREP: wsrep running threads now: 0
[Thread 0x7ffff7f32700 (LWP 20127) exited]
^C
Program received signal SIGINT, Interrupt.
0x00007ffff6a8203d in poll () at ../sysdeps/unix/syscall-template.S:81

file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) 
file: "../sysdeps/unix/syscall-template.S", line number: 1
(gdb) (gdb) thread apply all bt

Thread 10 (Thread 0x7fffe53f0700 (LWP 20124)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x00007fffed96899e in wait (this=0x7fffe53efce0, cond=...) at galerautils/src/gu_lock.hpp:56
#2  galera::ServiceThd::thd_func (arg=0x7fffee0ba590) at galera/src/galera_service_thd.cpp:30
#3  0x00007ffff7570182 in start_thread (arg=0x7fffe53f0700) at pthread_create.c:312
#4  0x00007ffff6a8f38d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 7 (Thread 0x7ffff7f7b700 (LWP 20102)):
#0  pthread_cond_wait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_wait.S:185
#1  0x0000000000ea3229 in safe_cond_wait (cond=0x1a13dc0 <COND_thread_count>, mp=0x1a12d00 <LOCK_thread_count>, file=0x106aa20 "/home/jan/mysql/10.0-galera/include/mysql/psi/mysql_thread.h", line=1154) at /home/jan/mysql/10.0-galera/mysys/thr_mutex.c:493
#2  0x00000000005b491e in inline_mysql_cond_wait (that=0x1a13dc0 <COND_thread_count>, mutex=0x1a12d00 <LOCK_thread_count>, src_file=0x106c700 "/home/jan/mysql/10.0-galera/sql/mysqld.cc", src_line=5717) at /home/jan/mysql/10.0-galera/include/mysql/psi/mysql_thread.h:1154
#3  0x00000000005bf25a in wsrep_wait_appliers_close (thd=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/mysqld.cc:5717
#4  0x000000000081305d in wsrep_stop_replication (thd=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/wsrep_mysqld.cc:774
#5  0x000000000081ddb8 in wsrep_provider_update (self=0x1a31ce0 <_ZL18Sys_wsrep_provider>, thd=0x7ffff0741070, type=OPT_GLOBAL) at /home/jan/mysql/10.0-galera/sql/wsrep_var.cc:238
#6  0x00000000005d7bc6 in sys_var::update (this=0x1a31ce0 <_ZL18Sys_wsrep_provider>, thd=0x7ffff0741070, var=0x7fffee1a1250) at /home/jan/mysql/10.0-galera/sql/set_var.cc:196
#7  0x00000000005da056 in set_var::update (this=0x7fffee1a1250, thd=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/set_var.cc:776
#8  0x00000000005d9c1e in sql_set_variables (thd=0x7ffff0741070, var_list=0x7ffff0745cc0) at /home/jan/mysql/10.0-galera/sql/set_var.cc:679
#9  0x00000000006829fc in mysql_execute_command (thd=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/sql_parse.cc:4084
#10 0x000000000068b47b in mysql_parse (thd=0x7ffff0741070, rawbuf=0x7fffee1a1088 "SET GLOBAL wsrep_provider= none", length=31, parser_state=0x7ffff7f7a1d0) at /home/jan/mysql/10.0-galera/sql/sql_parse.cc:6977
#11 0x000000000068abec in wsrep_mysql_parse (thd=0x7ffff0741070, rawbuf=0x7fffee1a1088 "SET GLOBAL wsrep_provider= none", length=31, parser_state=0x7ffff7f7a1d0) at /home/jan/mysql/10.0-galera/sql/sql_parse.cc:6799
#12 0x000000000067bf84 in dispatch_command (command=COM_QUERY, thd=0x7ffff0741070, packet=0x7fffefb8f071 "SET GLOBAL wsrep_provider= none", packet_length=31) at /home/jan/mysql/10.0-galera/sql/sql_parse.cc:1483
#13 0x000000000067ac9b in do_command (thd=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/sql_parse.cc:1088
#14 0x00000000007a50f5 in do_handle_one_connection (thd_arg=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/sql_connect.cc:1396
#15 0x00000000007a4e4d in handle_one_connection (arg=0x7ffff0741070) at /home/jan/mysql/10.0-galera/sql/sql_connect.cc:1307
#16 0x0000000000b42ad9 in pfs_spawn_thread (arg=0x7ffff5c226f0) at /home/jan/mysql/10.0-galera/storage/perfschema/pfs.cc:1860
#17 0x00007ffff7570182 in start_thread (arg=0x7ffff7f7b700) at pthread_create.c:312
#18 0x00007ffff6a8f38d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 4 (Thread 0x7ffff7fc4700 (LWP 20093)):
#0  0x00007ffff75780d1 in do_sigwait (sig=0x7ffff7fc3d90, set=<optimized out>) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:60
#1  __sigwait (set=0x7ffff7fc3dc0, sig=0x7ffff7fc3d90) at ../nptl/sysdeps/unix/sysv/linux/../../../../../sysdeps/unix/sysv/linux/sigwait.c:97
#2  0x00000000005ba49e in signal_hand (arg=0x0) at /home/jan/mysql/10.0-galera/sql/mysqld.cc:3481
#3  0x0000000000b42ad9 in pfs_spawn_thread (arg=0x7ffff5c208f0) at /home/jan/mysql/10.0-galera/storage/perfschema/pfs.cc:1860
#4  0x00007ffff7570182 in start_thread (arg=0x7ffff7fc4700) at pthread_create.c:312
#5  0x00007ffff6a8f38d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 3 (Thread 0x7ffff5bff700 (LWP 20092)):
#0  pthread_cond_timedwait@@GLIBC_2.3.2 () at ../nptl/sysdeps/unix/sysv/linux/x86_64/pthread_cond_timedwait.S:238
#1  0x0000000000ea352b in safe_cond_timedwait (cond=0x2240260 <COND_checkpoint>, mp=0x22401a0 <LOCK_checkpoint>, abstime=0x7ffff5bfed90, file=0x11825b0 "/home/jan/mysql/10.0-galera/include/mysql/psi/mysql_thread.h", line=1191) at /home/jan/mysql/10.0-galera/mysys/thr_mutex.c:547
#2  0x0000000000a8d3a9 in inline_mysql_cond_timedwait (that=0x2240260 <COND_checkpoint>, mutex=0x22401a0 <LOCK_checkpoint>, abstime=0x7ffff5bfed90, src_file=0x11825f0 "/home/jan/mysql/10.0-galera/storage/maria/ma_servicethread.c", src_line=119) at /home/jan/mysql/10.0-galera/include/mysql/psi/mysql_thread.h:1191
#3  0x0000000000a8d88f in my_service_thread_sleep (control=0x1847070 <checkpoint_control>, sleep_time=30000000000) at /home/jan/mysql/10.0-galera/storage/maria/ma_servicethread.c:118
#4  0x0000000000a8257a in ma_checkpoint_background (arg=0x1e) at /home/jan/mysql/10.0-galera/storage/maria/ma_checkpoint.c:709
#5  0x0000000000b42ad9 in pfs_spawn_thread (arg=0x7ffff5c20170) at /home/jan/mysql/10.0-galera/storage/perfschema/pfs.cc:1860
#6  0x00007ffff7570182 in start_thread (arg=0x7ffff5bff700) at pthread_create.c:312
#7  0x00007ffff6a8f38d in clone () at ../sysdeps/unix/sysv/linux/x86_64/clone.S:111

Thread 1 (Thread 0x7ffff7fc67c0 (LWP 20087)):
#0  0x00007ffff6a8203d in poll () at ../sysdeps/unix/syscall-template.S:81
#1  0x00000000005c1127 in handle_connections_sockets () at /home/jan/mysql/10.0-galera/sql/mysqld.cc:6859
#2  0x00000000005c00ca in mysqld_main (argc=119, argv=0x7ffff5c7e4c0) at /home/jan/mysql/10.0-galera/sql/mysqld.cc:6285
#3  0x00000000005b428d in main (argc=8, argv=0x7fffffffc7e8) at /home/jan/mysql/10.0-galera/sql/main.cc:25
(gdb)

Problem is that galera slave thread end signaling does not always work and there is no more slave threads but we still wait on condition variable.

Gliffy Diagrams

Attachments

Options
- Sort By Name
- Sort By Date
- Ascending
- Descending
- Thumbnails
- List
- Download All

Attachments

MDEV-6656.diff
3 kB
2014-08-29 01:44

Activity

Ascending order - Click to sort in descending order

Hide

Permalink

Nirbhay Choubey added a comment - 2014-08-29 01:44

Jan,
Can you check if the attached patch fixes the issue?

Show

Nirbhay Choubey added a comment - 2014-08-29 01:44 Jan, Can you check if the attached patch fixes the issue?

Hide

Permalink

Jan Lindström added a comment - 2014-08-29 10:02

revno: 3882
committer: Jan Lindström <jplindst@mariadb.org>
branch nick: 10.0-galera
timestamp: Fri 2014-08-29 09:42:13 +0300
message:
~~MDEV-6656~~: Test wsrep.variables hangs

Analysis: wsrep_applier_thread shutdown signaling does not always work
correctly causing a timing problem where main thread is waiting in a
condition variable a signal that all worker threads to end.

Show

Jan Lindström added a comment - 2014-08-29 10:02 revno: 3882 committer: Jan Lindström <jplindst@mariadb.org> branch nick: 10.0-galera timestamp: Fri 2014-08-29 09:42:13 +0300 message: MDEV-6656 : Test wsrep.variables hangs Analysis: wsrep_applier_thread shutdown signaling does not always work correctly causing a timing problem where main thread is waiting in a condition variable a signal that all worker threads to end.

People

Assignee:

Jan Lindström

Reporter:

Jan Lindström

Votes:

0 Vote for this issue

Watchers:

2 Start watching this issue

Dates

Created:

2014-08-28 15:25

Updated:

2014-08-29 10:02

Resolved:

2014-08-29 10:02

Time Tracking

Estimated:

Not Specified

Remaining:

Logged:

Agile

View on Board