[MDEV-30193] Data drift between source and replica with sync_binlog=0 and OS crash Created: 2022-12-10  Updated: 2022-12-12

Status: Open
Project: MariaDB Server
Component/s: None
Affects Version/s: None
Fix Version/s: None

Type: Bug Priority: Major
Reporter: Jaya Karthik Karri Assignee: Unassigned
Resolution: Unresolved Votes: 0
Labels: None
Environment:

MariaDB 10.4.27 running on Debian 10


 Description   

My intention for doing this test is to find out the data drift between source and replicas when a OS crash happens on source which is running with sync_binlog=0 and trx_commit=1.
In my test I saw two things
1> replication on replica is broken as after a crash, binlog information is missed from source as OS has not flushed from memory to file and gtid position is rolled back. Replica will try to look for a latest position which is not there on source and will fail to replicate. This is expected, no issues with this problem.
2> Data Drift- I observed the last transaction which was inserted on source by sysbench insert was rollback on source during crash recovery but this statement was committed on the replica. So my replica has these extra rows which were rollback on source.
My Questions:-
1> I thought data drift is something where source has more data than a replica?
2> My understanding from rollback on source during crash recovery is, while doing recovery it has not found the commit for the last transaction in redo logs so it rolled back the transaction. If commit was not there how can a replica committed that transaction coming from source.
Also how can a replica read a transaction which was not fully committed on the source, my assumption is the transaction is using internal XA commits and after the first phase, before committing the transaction it will write to binlog and once binlog is having some data then replica will read from it-- Not sure my assumption is right here?

From the error log I can see mariadb doing a redo crash recovery first and then binary log crash recovery.
I'm not pasting the info from error log or my table counts from both source and replicas and sysbench command I was running. If you need I can provide them.

How I did an OS crash?
My DB server is running on a VM, through v-center I did a hard stop of VM which did a crash. I tested this scenario multiple times and every time I saw a data drift, more data on Replicas.

Sysbench- I was just running the prepare statement which created tables and inserts data into them, was using 4 parallel threads, inserting into 4 tables at a time.

Server- 4 CPU and 4 GB Ram, around 1.5 GB innodb buffer pool. Debian 10

Let me know if you need any more information.

Regards
Jaya

 Comments   
Comment by Alice Sherepa [ 2022-12-12 ]

Could you please add the error log and if possible - the way to repeat the problem?

Comment by Jaya Karthik Karri [ 2022-12-12 ]

Hi Alice Sherepa,
To reproduce the error, Setup two mariadb servers with master-slave topology. Configure sync_binlog on source as 0 and install sysbench and use below command to create tables in sbtest database. While the row are being inserted into the tables, hard crash the VM of the source, as my VM is configured through V-center I used v-center console to hard stop the VM. Once the source VM is restarted after hard crash you can check the replication issues and data differences.

sysbench /usr/share/sysbench/oltp_write_only.lua --threads=4 --mysql-user=root --mysql-port=3306 --tables=10 --table-size=1000000 --rand-type=special prepare
Note:- Don't crash the VM when sysbench is running this command - creating secondary indexes, as you wont get the data differences in this case.

Error log after the hard crash

2022-12-07  9:04:11 0 [Note] InnoDB: Using Linux native AIO
 
2022-12-07  9:04:11 0 [Note] InnoDB: Mutexes and rw_locks use GCC atomic builtins
 
2022-12-07  9:04:11 0 [Note] InnoDB: Uses event mutexes
 
2022-12-07  9:04:11 0 [Note] InnoDB: Compressed tables use zlib 1.2.11
 
2022-12-07  9:04:11 0 [Note] InnoDB: Number of pools: 1
 
2022-12-07  9:04:11 0 [Note] InnoDB: Using SSE2 crc32 instructions
 
2022-12-07  9:04:11 0 [Note] InnoDB: Initializing buffer pool, total size = 1.5G, instances = 2, chunk size = 128M
 
2022-12-07  9:04:11 0 [Note] InnoDB: Completed initialization of buffer pool
 
2022-12-07  9:04:11 0 [Note] InnoDB: If the mysqld execution user is authorized, page cleaner thread priority can be changed. See the man page of setpriority().
 
2022-12-07  9:04:11 0 [Note] InnoDB: Starting crash recovery from checkpoint LSN=82182364372
 
2022-12-07  9:04:16 0 [Note] InnoDB: Transaction 35211874 was in the XA prepared state.
 
2022-12-07  9:04:16 0 [Note] InnoDB: 2 transaction(s) which must be rolled back or cleaned up in total 20 row operations to undo
 
2022-12-07  9:04:16 0 [Note] InnoDB: Trx id counter is 35211884
 
2022-12-07  9:04:16 0 [Note] InnoDB: Starting final batch to recover 21034 pages from redo log.
 
2022-12-07  9:04:18 0 [Note] InnoDB: Last binlog file '/var/log/mysql/binlogs/mysql-bin-d-mysql-220.000016', position 628955039
 
2022-12-07  9:04:18 0 [Note] InnoDB: 128 out of 128 rollback segments are active.
 
2022-12-07  9:04:18 0 [Note] InnoDB: Starting in background the rollback of recovered transactions
 
2022-12-07  9:04:18 0 [Note] InnoDB: Removed temporary tablespace data file: "ibtmp1"
 
2022-12-07  9:04:18 0 [Note] InnoDB: Creating shared tablespace for temporary tables
 
2022-12-07  9:04:18 0 [Note] InnoDB: Setting file './ibtmp1' size to 12 MB. Physically writing the file full; Please wait ...
 
2022-12-07  9:04:18 0 [Note] InnoDB: File './ibtmp1' size is now 12 MB.
 
2022-12-07  9:04:18 0 [Note] InnoDB: Rolled back recovered transaction 35211881
 
2022-12-07  9:04:18 0 [Note] InnoDB: Rollback of non-prepared transactions completed
 
2022-12-07  9:04:18 0 [Note] InnoDB: Waiting for purge to start
 
2022-12-07  9:04:18 0 [Note] InnoDB: 10.4.27 started; log sequence number 82276175863; transaction id 35211886
 
2022-12-07  9:04:18 0 [Note] InnoDB: Loading buffer pool(s) from /var/lib/mysql/ib_buffer_pool
 
2022-12-07  9:04:18 0 [Note] Plugin 'FEEDBACK' is disabled.
 
221207  9:04:18 server_audit: INCL_DML_USERS and EXCL_DML_USERS specified simultaneously - both set to empty
 
221207  9:04:18 server_audit: server_audit_incl_users set to ''.
 
221207  9:04:18 server_audit: MariaDB Audit Plugin version 1.4.14 STARTED.
 
221207  9:04:18 server_audit: logging started to the file /var/log/mysql/mysql-audit-d-mysql-220.log.
 
2022-12-07  9:04:18 0 [Note] Recovering after a crash using /var/log/mysql/binlogs/mysql-bin-d-mysql-220
 
2022-12-07  9:04:18 0 [Note] InnoDB: Buffer pool(s) load completed at 221207  9:04:18
 
2022-12-07  9:04:20 0 [Note] Starting crash recovery...
 
2022-12-07  9:04:20 0 [Note] InnoDB: Starting recovery for XA transactions...
 
2022-12-07  9:04:20 0 [Note] InnoDB: Transaction 35211874 in prepared state after recovery
 
2022-12-07  9:04:20 0 [Note] InnoDB: Transaction contains changes to 2688 rows
 
2022-12-07  9:04:20 0 [Note] InnoDB: 1 transactions in prepared state after recovery
 
2022-12-07  9:04:20 0 [Note] Found 1 prepared transaction(s) in InnoDB
 
2022-12-07  9:04:20 0 [Note] Crash recovery finished.
 
2022-12-07  9:04:20 0 [Note] Server socket created on IP: '0.0.0.0'.
 
2022-12-07  9:04:20 7 [Note] Event Scheduler: scheduler thread started with id 7
 
2022-12-07  9:04:20 0 [Note] Reading of all Master_info entries succeeded
 
2022-12-07  9:04:20 0 [Note] Added new Master_info '' to hash table
 
2022-12-07  9:04:20 0 [Note] /usr/sbin/mysqld: ready for connections.
 
1947 Version: '10.4.27-MariaDB-1:10.4.27+maria~deb10-log'  socket: '/var/run/mysqld/mysqld.sock'  port: 3306  mariadb.org binary distribution
 
2022-12-07  9:04:20 11 [Note] Start binlog_dump to slave_server(4128270), pos(mysql-bin-d-mysql-220.000016, 629989501), using_gtid(1), gtid('1-4128220-7415')
 
2022-12-07  9:04:20 13 [Note] Start binlog_dump to slave_server(4128230), pos(mysql-bin-d-mysql-220.000016, 629989501), using_gtid(1), gtid('1-4128220-7415')

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