Bug #104287 trx_sys binlog coordinates broken after clone plugin
Submitted: 12 Jul 2021 13:39 Modified: 14 Jul 2021 11:24
Reporter: Marcelo Altmann (OCA) Email Updates:
Status: Not a Bug Impact on me:
None 
Category:MySQL Server: Clone Plugin Severity:S3 (Non-critical)
Version:8.0.17 OS:Any
Assigned to: CPU Architecture:Any

[12 Jul 2021 13:39] Marcelo Altmann
Description:
After the introduction of the clone plugin, binlog coordinates stored on ibdata1 file are not been updated:

8.0.16:

mysql> CREATE DATABASE test;
Query OK, 1 row affected (0,02 sec)

mysql> use test;
Database changed
mysql> CREATE TABLE p (a INT) ENGINE=InnoDB;
Query OK, 0 rows affected (0,03 sec)

mysql>     INSERT INTO p VALUES (1), (2), (3);
Query OK, 3 rows affected (0,02 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+-------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+---------------+----------+--------------+------------------+-------------------+
| binlog.000001 |      823 |              |                  |                   |
+---------------+----------+--------------+------------------+-------------------+
1 row in set (0,00 sec)

mysql> \! /work/eng-scripts/innodb_read_binlog_info_from_ibdata.sh /work/mysql/ins/8.0/datadir1/ibdata1
Binlog Name and Position : binlog.000001 823
mysql>     INSERT INTO p VALUES (1), (2), (3);
Query OK, 3 rows affected (0,01 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+-------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+---------------+----------+--------------+------------------+-------------------+
| binlog.000001 |     1105 |              |                  |                   |
+---------------+----------+--------------+------------------+-------------------+
1 row in set (0,00 sec)

mysql> \! /work/eng-scripts/innodb_read_binlog_info_from_ibdata.sh /work/mysql/ins/8.0/datadir1/ibdata1
Binlog Name and Position : binlog.000001 1105
mysql>

8.0.17:

mysql> CREATE DATABASE test;
Query OK, 1 row affected (0.01 sec)

mysql> use test;
Database changed
mysql> CREATE TABLE p (a INT) ENGINE=InnoDB;
Query OK, 0 rows affected (0.03 sec)

mysql> INSERT INTO p VALUES (1), (2), (3);
Query OK, 3 rows affected (0.01 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+-------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+---------------+----------+--------------+------------------+-------------------+
| binlog.000001 |      823 |              |                  |                   |
+---------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

mysql> \! /work/eng-scripts/innodb_read_binlog_info_from_ibdata.sh /work/mysql/ins/8.0/datadir1/ibdata1
Binlog is not stored in /work/mysql/ins/8.0/datadir1/ibdata1
mysql> INSERT INTO p VALUES (1), (2), (3);
Query OK, 3 rows affected (0.02 sec)
Records: 3  Duplicates: 0  Warnings: 0

mysql> SHOW MASTER STATUS;
+---------------+----------+--------------+------------------+-------------------+
| File          | Position | Binlog_Do_DB | Binlog_Ignore_DB | Executed_Gtid_Set |
+---------------+----------+--------------+------------------+-------------------+
| binlog.000001 |     1105 |              |                  |                   |
+---------------+----------+--------------+------------------+-------------------+
1 row in set (0.00 sec)

mysql> \! /work/eng-scripts/innodb_read_binlog_info_from_ibdata.sh /work/mysql/ins/8.0/datadir1/ibdata1
Binlog is not stored in /work/mysql/ins/8.0/datadir1/ibdata1
 

This breaks backup tools such as Xtrabackup that rely on trx_sys binlog coordinates. 

How to repeat:
Read binlog coordinates directly from ibdata using below sample shell script:

------- innodb_read_binlog_info_from_ibdata.sh  ------- 
#!/bin/bash

FILE=$1
read_binlog_info_from_ibd() {
  TRX_SYS_MYSQL_LOG_MAGIC_N=873422344
  TRX_SYS=$((5* 16384 + 38 + 15384))
  TRX_SYS_MYSQL_LOG_MAGIC_N_FLD=$(xxd -b -s $((${TRX_SYS})) -l4 $FILE |  awk '{print $2 $3 $4 $5}')
  TRX_SYS_MYSQL_LOG_MAGIC_N_FLD_D=$((2#$TRX_SYS_MYSQL_LOG_MAGIC_N_FLD))

  if [[ ${TRX_SYS_MYSQL_LOG_MAGIC_N_FLD_D} -ne ${TRX_SYS_MYSQL_LOG_MAGIC_N} ]];
  then
    echo "Binlog is not stored in ${FILE}"
    exit 0
  fi

  TRX_SYS_MYSQL_LOG_NAME_LEN=512
  TRX_SYS_MYSQL_LOG_NAME=12

  BINLOG_NAME=$(xxd -p -s $((${TRX_SYS} + ${TRX_SYS_MYSQL_LOG_NAME})) -l${TRX_SYS_MYSQL_LOG_NAME_LEN} $FILE | xxd -r -p |  tr -d '\0')

  TRX_SYS_MYSQL_LOG_OFFSET_HIGH=4
  TRX_SYS_MYSQL_LOG_OFFSET_LOW=8

  HIGH=$(xxd -b -s $((${TRX_SYS} + ${TRX_SYS_MYSQL_LOG_OFFSET_HIGH})) -l4 $FILE |  awk '{print $2 $3 $4 $5}')
  HIGH_D=$((2#$HIGH))
  LOW=$(xxd -b -s $((${TRX_SYS} + ${TRX_SYS_MYSQL_LOG_OFFSET_LOW})) -l4 $FILE |  awk '{print $2 $3 $4 $5}')
  LOW_D=$((2#$LOW))
  OFFSET=$HIGH_D
  ((OFFSET <<= 32))
  ((OFFSET|=LOW_D))

  echo "Binlog Name and Position : ${BINLOG_NAME} ${OFFSET}"
  exit 0
}
read_binlog_info_from_ibd
----------------------------------- 

1) create a table and insert some data:

CREATE TABLE p (a INT) ENGINE=InnoDB;
INSERT INTO p VALUES (1), (2), (3);

2) Read MASTER data:

SHOW MASTER STATUS

3) Wait until all pages have been flushed to disk and check what is stored in the file:

innodb_read_binlog_info_from_ibdata.sh  /var/lib/mysql/ibdata1

repeat the process on 8.0.16 (working) and in any other version after it to see the difference. 

Suggested fix:
Keep trx_sys binlog information updated on ibdata regardless of clone.
[14 Jul 2021 7:49] Debarun Banerjee
During clone implementation, we decided to remove the unconditional update of binary log position in trx sys page. 

The primary reason was the saved position has correctness issue as the innodb commit doesn't necessarily happen in the same order the transaction logs are written in binary log.

It also has impact on performance as it creates another serialisation point for all transactions asking for page-0 X latch on system tablespace. 

Finally, I think it is better not to have dependency on undocumented internal information within innodb data files because they could change anytime in future versions.
[14 Jul 2021 8:56] MySQL Verification Team
Thank you Deb for the details.
Since this behavior is by design hence closing this report as *Not a Bug*.

regards,
Umesh
[14 Jul 2021 11:24] Marcelo Altmann
Hi Debarun and Umesh.

We agree with your analyzes. After the creation of The log_status Table, we can use it to get an (almost) lockless snapshot of storage engines (InnoDB / binlog / ...)

Thanks for your explanation on it.