[MDEV-8019] rpl.rpl_semi_sync_event 'innodb_plugin,row' sporadically produces warnings in buildbot on P8 Created: 2015-04-19  Updated: 2016-06-08  Resolved: 2016-06-08

Status: Closed
Project: MariaDB Server
Component/s: Tests
Affects Version/s: 5.5
Fix Version/s: N/A

Type: Bug Priority: Minor
Reporter: Elena Stepanova Assignee: Jan Lindström (Inactive)
Resolution: Cannot Reproduce Votes: 0
Labels: tests

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

 Description   

http://buildbot.askmonty.org/buildbot/builders/p8-rhel71-bintar-debug/builds/230/steps/test/logs/stdio

rpl.rpl_semi_sync_event 'innodb_plugin,row' w2 [ pass ]  25556
 
worker[2] > Restart [mysqld.1 - pid: 12005, winpid: 12005] - running with different options '--binlog-format=row --ignore-builtin-innodb --plugin-load=ha_innodb.so --innodb --innodb-cmpmem --innodb-trx --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --log-bin=master-bin' != '--binlog-format=row --ignore-builtin-innodb --plugin-load=ha_innodb.so --innodb --innodb-cmpmem --innodb-trx --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --log-bin=master-bin --max-connections=40'
 
worker[2] > Restart [mysqld.2 - pid: 12012, winpid: 12012] - running with different options '--binlog-format=row --ignore-builtin-innodb --plugin-load=ha_innodb.so --innodb --innodb-cmpmem --innodb-trx --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --log-bin=slave-bin --loose-innodb-lock-wait-timeout=4 --slave-transaction-retries=2 --max-relay-log-size=4096' != '--binlog-format=row --ignore-builtin-innodb --plugin-load=ha_innodb.so --innodb --innodb-cmpmem --innodb-trx --innodb-buffer-pool-stats --innodb-buffer-page --innodb-buffer-page-lru --log-bin=slave-bin'
 
***Warnings generated in error logs during shutdown after running tests: rpl.rpl_semi_sync_event
 
 
 
Warning:  520 bytes lost, allocated at sql/rpl_handler.cc:266, sql/log.cc:6053, sql/log.cc:5893, sql/log.cc:5856, sql/log.cc:1661, sql/log.cc:1741, sql/log.cc:7470, sql/handler.cc:1322

Error log

 
CURRENT_TEST: rpl.rpl_semi_sync_event
 
150416  6:42:49 [Note] Plugin 'XTRADB_ADMIN_COMMAND' is disabled.
 
150416  6:42:49 [Note] Plugin 'partition' is disabled.
 
150416  6:42:49 InnoDB: !!!!!!!! UNIV_DEBUG switched on !!!!!!!!!
 
150416  6:42:49 InnoDB: The InnoDB memory heap is disabled
 
150416  6:42:49 InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
150416  6:42:49 InnoDB: Compressed tables use zlib 1.2.8
 
150416  6:42:49 InnoDB: Using Linux native AIO
 
150416  6:42:49 InnoDB: Initializing buffer pool, size = 8.0M
 
150416  6:42:49 InnoDB: Completed initialization of buffer pool
 
InnoDB: The first specified data file ./ibdata1 did not exist:
 
InnoDB: a new database to be created!
 
150416  6:42:49  InnoDB: Setting file ./ibdata1 size to 10 MB
 
InnoDB: Database physically writes the file full: wait...
 
150416  6:42:51  InnoDB: Log file ./ib_logfile0 did not exist: new to be created
 
InnoDB: Setting log file ./ib_logfile0 size to 5 MB
 
InnoDB: Database physically writes the file full: wait...
 
150416  6:42:53  InnoDB: Log file ./ib_logfile1 did not exist: new to be created
 
InnoDB: Setting log file ./ib_logfile1 size to 5 MB
 
InnoDB: Database physically writes the file full: wait...
 
InnoDB: Doublewrite buffer not found: creating new
 
InnoDB: Doublewrite buffer created
 
InnoDB: 127 rollback segment(s) active.
 
InnoDB: Creating foreign key constraint system tables
 
InnoDB: Foreign key constraint system tables created
 
150416  6:43:10  InnoDB: Waiting for the background threads to start
 
150416  6:43:11 InnoDB: 5.5.42-MariaDB started; log sequence number 0
 
150416  6:43:11 [Note] Plugin 'INNODB_LOCK_WAITS' is disabled.
 
150416  6:43:11 [Note] Plugin 'INNODB_CMP' is disabled.
 
150416  6:43:11 [Note] Plugin 'INNODB_CMP_RESET' is disabled.
 
150416  6:43:11 [Note] Plugin 'INNODB_CMPMEM_RESET' is disabled.
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown variable 'loose-feedback-user-info=mysql-test'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages-blob'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-buffer-pool-pages-index'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-changed-pages'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-index-stats'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-rseg'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-columns'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-fields'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-foreign'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-foreign-cols'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-indexes'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-stats'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-tables'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-sys-tablestats'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-table-stats'
 
150416  6:43:11 [Warning] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: unknown option '--loose-skip-innodb-undo-logs'
 
150416  6:43:11 [Note] Server socket created on IP: '0.0.0.0'.
 
150416  6:43:11 [Note] Event Scheduler: Loaded 0 events
 
150416  6:43:11 [Note] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: ready for connections.
 
Version: '5.5.42-MariaDB-debug-log'  socket: '/home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/mysql-test/var/tmp/2/mysqld.1.sock'  port: 16040  Source distribution
 
150416  6:43:14 [Note] Semi-sync replication initialized for transactions.
 
150416  6:43:14 [Note] Semi-sync replication enabled on the master.
 
150416  6:43:15 [Note] Start semi-sync binlog_dump to slave (server_id: 2), pos(master-bin.000001, 1333)
 
150416  6:43:15 [Note] Stop asynchronous binlog_dump to slave (server_id: 2)
 
150416  6:43:15 [Note] Event Scheduler: scheduler thread started with id 9
 
150416  6:43:15 [ERROR] Read semi-sync reply network error:  (errno: 1158)
 
150416  6:43:15 [Note] Stop semi-sync binlog_dump to slave (server_id: 2)
 
150416  6:43:16 [Note] Event Scheduler: Killing the scheduler thread, thread id 9
 
150416  6:43:16 [Note] Event Scheduler: Waiting for the scheduler thread to reply
 
150416  6:43:16 [Note] Event Scheduler: Stopped
 
150416  6:43:25 [Warning] Timeout waiting for reply of binlog (file: master-bin.000001, pos: 2770), semi-sync up to file master-bin.000001, position 2583.
 
150416  6:43:25 [Note] Semi-sync replication switched OFF.
 
150416  6:43:25 [Note] unregister_replicator OK
 
150416  6:43:40 [Note] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: Normal shutdown
 
 
 
150416  6:43:40 [Note] Event Scheduler: Purging the queue. 0 events
 
150416  6:43:40  InnoDB: Starting shutdown...
 
150416  6:43:43  InnoDB: Shutdown completed; log sequence number 1632968
 
150416  6:43:43 [Note] Debug sync points hit:                   4073
 
150416  6:43:43 [Note] Debug sync points executed:              0
 
150416  6:43:43 [Note] Debug sync points max active per thread: 0
 
150416  6:43:43 [Note] /home/buildbot/maria-slave/power8-vlp06-bintar-debug/build/sql/mysqld: Shutdown complete
 
 
 
Warning:  520 bytes lost, allocated at sql/rpl_handler.cc:266, sql/log.cc:6053, sql/log.cc:5893, sql/log.cc:5856, sql/log.cc:1661, sql/log.cc:1741, sql/log.cc:7470, sql/handler.cc:1322
 
Memory lost: 520 bytes in 1 chunks

It's hard to say how often it happens, because it's not recorded as a failure in buildbot.

 Comments   
Comment by Jan Lindström (Inactive) [ 2015-12-08 ]

Hmm, not very easy to repeat, I used./mysql-test-run --mem rpl.rpl_semi_sync_event,innodb_plugin,row --repeat=200 on P8, could not repeat.

Comment by Jan Lindström (Inactive) [ 2016-06-08 ]

Looked buildbot and latest 10 5.5 builds, can't find this repeated and my own testing did also not repeat this. If reappears, this can be re-opened.

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