[MDEV-10627] rpl.rpl_circular_for_4_hosts fails with timeout in buildbot Created: 2016-08-21  Updated: 2017-02-21  Resolved: 2017-02-21

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 10.0, 10.1
Fix Version/s: N/A

Type: Bug Priority: Major
Reporter: Elena Stepanova Assignee: Elena Stepanova
Resolution: Fixed Votes: 0
Labels: None

Issue Links:
Relates
relates to MDEV-7069 Fix buildbot failures in main server ... Stalled
Sprint: 5.5.55

 Description   

http://buildbot.askmonty.org/buildbot/builders/p8-trusty-bintar/builds/21/steps/test/logs/stdio

rpl.rpl_circular_for_4_hosts 'innodb_plugin,stmt' w2 [ fail ]  timeout after 900 seconds
 
        Test ended at 2016-06-30 03:05:42
 
worker[2] > Restart  - using different config file
 
worker[2] > Restart  - using different config file
 
worker[2] > Restart  - using different config file
 
worker[2] > Restart  - using different config file
 
 
 
Test case timeout after 900 seconds
 
 
 
== /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/2/log/rpl_circular_for_4_hosts.log == 
Master B	A	100
 
Master B	B	100
 
Master B	C	100
 
Master B	D	100
 
SELECT 'Master C',b,COUNT(*) FROM t2 WHERE c = 1 GROUP BY b ORDER BY b;
 
Master C	b	COUNT(*)
 
Master C	A	100
 
Master C	B	100
 
Master C	C	100
 
Master C	D	100
 
SELECT 'Master D',b,COUNT(*) FROM t2 WHERE c = 1 GROUP BY b ORDER BY b;
 
Master D	b	COUNT(*)
 
Master D	A	100
 
Master D	B	100
 
Master D	C	100
 
Master D	D	100
 
 
 
* Transactions with rollbacks *
 
BEGIN;
 
BEGIN;
 
 
 
The server [mysqld.4 - pid: 17579, winpid: 17579, exit: 256] crashed while running 'analyze-timeout'
 
Server log from this test:
 
----------SERVER LOG START-----------
 
2016-06-30  2:49:04 70367031291632 [Note] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld (mysqld 10.1.15-MariaDB) starting as process 17580 ...
 
2016-06-30  2:49:04 70367031291632 [Warning] Could not increase number of max_open_files to more than 1024 (request: 4162)
 
2016-06-30  2:49:04 70367031291632 [Note] Plugin 'partition' is disabled.
 
2016-06-30  2:49:04 70367031291632 [Note] Plugin 'SEQUENCE' is disabled.
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Using mutexes to ref count buffer pool pages
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: The InnoDB memory heap is disabled
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: GCC builtin __atomic_thread_fence() is used for memory barrier
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Compressed tables use zlib 1.2.3
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Using Linux native AIO
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Using POWER8 crc32 instructions
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Initializing buffer pool, size = 8.0M
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Completed initialization of buffer pool
 
2016-06-30  2:49:04 70367031291632 [Note] InnoDB: Highest supported file format is Barracuda.
 
2016-06-30  2:49:11 70367031291632 [Note] InnoDB: 128 rollback segment(s) are active.
 
2016-06-30  2:49:11 70367031291632 [Note] InnoDB: Waiting for purge to start
 
2016-06-30  2:49:12 70367031291632 [Note] InnoDB: 5.6.31 started; log sequence number 1629517
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_DATAFILES' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_TABLESTATS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_CMP' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'XTRADB_READ_VIEW' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'XTRADB_RSEG' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_DELETED' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'CHANGED_PAGE_BITMAPS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_TABLESPACES_ENCRYPTION' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_FIELDS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'XTRADB_INTERNAL_HASH_TABLES' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_TABLESPACES_SCRUBBING' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_INDEX_TABLE' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_BEING_DELETED' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_MUTEXES' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_CONFIG' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'FEEDBACK' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_INDEX_CACHE' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_FT_DEFAULT_STOPWORD' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_COLUMNS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_CMP_PER_INDEX_RESET' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_TABLESPACES' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_SEMAPHORE_WAITS' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Note] Plugin 'INNODB_SYS_INDEXES' is disabled.
 
2016-06-30  2:49:29 70367031291632 [Warning] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-startup-interval=20'
 
2016-06-30  2:49:29 70367031291632 [Warning] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-first-interval=60'
 
2016-06-30  2:49:29 70367031291632 [Warning] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: unknown variable 'loose-feedback-debug-interval=60'
 
2016-06-30  2:49:29 70367031291632 [Warning] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: unknown option '--loose-skip-plugin-innodb-changed-pages'
 
2016-06-30  2:49:29 70367031291632 [Warning] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: unknown variable 'loose-debug-sync-timeout=300'
 
2016-06-30  2:49:29 70366730907968 [Note] InnoDB: Dumping buffer pool(s) not yet started
 
2016-06-30  2:49:29 70367031291632 [Note] Server socket created on IP: '127.0.0.1'.
 
2016-06-30  2:49:29 70367031291632 [Note] /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld: ready for connections.
 
Version: '10.1.15-MariaDB'  socket: '/var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/tmp/2/mysqld.4.sock'  port: 16023  MariaDB Server
 
2016-06-30  2:49:30 70367020807488 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='', master_port='3306', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16022', master_log_file='master-bin.000001', master_log_pos='4'.
 
2016-06-30  2:49:30 70366809912640 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 4, relay log './mysqld-relay-bin.000001' position: 4
 
2016-06-30  2:49:30 70366810305856 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16022',replication started in log 'master-bin.000001' at position 4
 
2016-06-30  2:50:29 70366809912640 [Note] Error reading relay log event: slave SQL thread was killed
 
2016-06-30  2:50:29 70366810305856 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
2016-06-30  2:50:29 70366810305856 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2142
 
2016-06-30  2:50:29 70366810305856 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 2142, relay log './mysqld-relay-bin.000002' position: 1756
 
2016-06-30  2:50:29 70366809912640 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16022',replication started in log 'master-bin.000001' at position 2142
 
2016-06-30  2:50:29 70366810305856 [Note] 'SQL_SLAVE_SKIP_COUNTER=1' executed at relay_log_file='./mysqld-relay-bin.000002', relay_log_pos='1756', master_log_name='master-bin.000001', master_log_pos='2142' and new position at relay_log_file='./mysqld-relay-bin.000003', relay_log_pos='748', master_log_name='master-bin.000001', master_log_pos='2352' 
2016-06-30  2:50:29 70366810305856 [Note] Error reading relay log event: slave SQL thread was killed
 
2016-06-30  2:50:29 70366809912640 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
2016-06-30  2:50:29 70366809912640 [Note] Slave I/O thread exiting, read up to log 'master-bin.000001', position 2701
 
2016-06-30  2:50:29 70367020807488 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16022', master_log_file='master-bin.000001', master_log_pos='2701'. New state master_host='127.0.0.1', master_port='16021', master_log_file='slave-bin.000001', master_log_pos='2141'.
 
2016-06-30  2:50:29 70366809912640 [Note] Slave SQL thread initialized, starting replication in log 'slave-bin.000001' at position 2141, relay log './mysqld-relay-bin.000001' position: 4
 
2016-06-30  2:50:29 70366810305856 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16021',replication started in log 'slave-bin.000001' at position 2141
 
2016-06-30  2:50:29 70366809912640 [Note] Error reading relay log event: slave SQL thread was killed
 
2016-06-30  2:50:29 70366810305856 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
2016-06-30  2:50:29 70366810305856 [Note] Slave I/O thread exiting, read up to log 'slave-bin.000001', position 58031
 
2016-06-30  2:50:30 70367020807488 [Note] 'CHANGE MASTER TO executed'. Previous state master_host='127.0.0.1', master_port='16021', master_log_file='', master_log_pos='4'. New state master_host='127.0.0.1', master_port='16022', master_log_file='master-bin.000001', master_log_pos='314'.
 
2016-06-30  2:50:30 70366810305856 [Note] Slave SQL thread initialized, starting replication in log 'master-bin.000001' at position 314, relay log './mysqld-relay-bin.000001' position: 4
 
2016-06-30  2:50:30 70366809912640 [Note] Slave I/O thread: connected to master 'root@127.0.0.1:16022',replication started in log 'master-bin.000001' at position 314
 
2016-06-30  3:04:46 70366809912640 [ERROR] Error reading packet from server: Lost connection to MySQL server during query ( server_errno=2013)
 
2016-06-30  3:04:46 70366809912640 [Note] Slave I/O thread: Failed reading log event, reconnecting to retry, log 'master-bin.000001' at position 102674
 
2016-06-30  3:04:46 70366809912640 [ERROR] Slave I/O: error reconnecting to master 'root@127.0.0.1:16022' - retry-time: 1  retries: 86400  message: Lost connection to MySQL server at 'reading initial communication packet', system error: 104 "Connection reset by peer", Internal MariaDB error code: 2013
 
160630  3:04:46 [ERROR] mysqld got signal 6 ;
 
This could be because you hit a bug. It is also possible that this binary
 
or one of the libraries it was linked against is corrupt, improperly built,
 
or misconfigured. This error can also be caused by malfunctioning hardware.
 
 
 
To report this bug, see https://mariadb.com/kb/en/reporting-bugs
 
 
 
We will try our best to scrape up some info that will hopefully help
 
diagnose the problem, but since we have already crashed, 
something is definitely wrong and this may fail.
 
 
 
Server version: 10.1.15-MariaDB
 
key_buffer_size=1048576
 
read_buffer_size=131072
 
max_used_connections=3
 
max_threads=153
 
thread_count=0
 
It is possible that mysqld could use up to 
key_buffer_size + (read_buffer_size + sort_buffer_size)*max_threads = 62889 K  bytes of memory
 
Hope that's ok; if not, decrease some variables in the equation.
 
 
 
Thread pointer: 0x0x0
 
Attempting backtrace. You can use the following information to find out
 
where mysqld died. If you see no messages after this, something went
 
terribly wrong...
 
stack_bottom = 0x0 thread_stack 0x48400
 
/var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld(my_print_stacktrace+0x64)[0x54119dd4]
 
/var/lib/buildbot/maria-slave/p8-trusty-bintar/build/sql/mysqld(handle_fatal_signal+0x460)[0x53b06140]
 
linux-vdso64.so.1(__kernel_sigtramp_rt64+0x0)[0x3fff99e00478]
 
/opt/at8.0/lib64/power8/libc.so.6(__poll+0x58)[0x3fff99721438]
 
[0x3fff986a0dd0]
 
/opt/at8.0/lib64/power8/libc.so.6(__poll_chk+0x24)[0x3fff9974a0c4]
 
mysys/stacktrace.c:246(my_print_stacktrace)[0x53854938]
 
bits/poll2.h:41(poll)[0x5385f2e8]
 
sql/main.cc:25(main)[0x53839620]
 
/opt/at8.0/lib64/power8/libc.so.6(+0x22a00)[0x3fff99622a00]
 
/opt/at8.0/lib64/power8/libc.so.6(__libc_start_main+0xc4)[0x3fff99622c14]
 
The manual page at http://dev.mysql.com/doc/mysql/en/crashing.html contains
 
information that should help you find out what is causing the crash.
 
Writing a core file
 
----------SERVER LOG END-------------
 
 
 
 - saving '/var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/2/log/rpl.rpl_circular_for_4_hosts-innodb_plugin,stmt/' to '/var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/log/rpl.rpl_circular_for_4_hosts-innodb_plugin,stmt/'
 
 - found 'core' (4/5)
 
 
 
Trying 'dbx' to get a backtrace
 
 
 
Trying 'gdb' to get a backtrace
 
Compressed file /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/log/rpl.rpl_circular_for_4_hosts-innodb_plugin,stmt/mysqld.4/data/core
 
***Warnings generated in error logs during shutdown after running tests: rpl.rpl_circular_for_4_hosts
 
 
 
Attempting backtrace. You can use the following information to find out
 
Attempting backtrace. You can use the following information to find out
 
2016-06-30  2:50:29 70366267667776 [Warning] Slave: Duplicate entry '6' for key 'PRIMARY' Error_code: 1062
 
Attempting backtrace. You can use the following information to find out
 
Attempting backtrace. You can use the following information to find out
 
 
 
worker[2] mysql-test-run: WARNING: Waited 60 seconds for /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/2/run/mysqld.1.pid to be created, still waiting for 120 seconds...
 
worker[2] mysql-test-run: WARNING: Waited 120 seconds for /var/lib/buildbot/maria-slave/p8-trusty-bintar/build/mysql-test/var/2/run/mysqld.1.pid to be created, still waiting for 60 seconds...
 
worker[2] mysql-test-run: WARNING: Timeout after mysql-test-run waited 180 seconds for the process [mysqld.1 - pid: 20568, winpid: 20568] to create a pid file.



 Comments   
Comment by Elena Stepanova [ 2017-02-21 ]

The timeout has been only observed on p8-trusty-bintar and p8-trusty-bintar-debug biulders (and on the experimental mac builder).
After p8* builders had been switched to running with --mem, average execution time for the test has gone down from ~110 seconds to ~3 seconds (on p8-trusty-bintar), and similarly decreased on p8-trusty-bintar-debug. Hopefully it will allow to get rid of the timeouts.

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