xtrbackup:Cannot recover a trunc

作者: 重庆八怪 | 来源:发表于2021-12-22 10:57 被阅读0次

这个问题实际上已经网友遇到过了，我们再来简单的分析一下，因为我也遇到了一次。

一、 xtrbackup的报错

其实就是xtrbackup报下面的错：

ER_IB_MSG_1077 eng "Undo tablespace number %lu was being truncated when mysqld quit."
ER_IB_MSG_1078 eng "Cannot recover a truncated undo tablespace in read-only mode"

抛错点
  if (!undo::is_active_truncate_log_present(space_num)) { //检测是否存在 trunc.log文件
    return (DB_SUCCESS);
  }

  ib::info(ER_IB_MSG_1077, ulong{space_num});//如果存在报错 ER_IB_MSG_1077

  if (srv_read_only_mode) {
    ib::error(ER_IB_MSG_1078); //xtrbackup始终未read only模式报错 ER_IB_MSG_1078
    return (DB_READ_ONLY);
  }

其中log文件的名字后缀为undo_trunc.log

  size_t size = strlen(srv_log_group_home_dir) + 22 + 1 /* NUL */
                + strlen(undo::s_log_prefix) + strlen(undo::s_log_ext)

/** Truncate Log file Prefix. */
const char *const s_log_prefix = "undo_";

/** Truncate Log file Extension. */
const char *const s_log_ext = "trunc.log";

二、 undo的segment初始化和使用

undo segment一共128个，前面32位temp segment供临时表使用，后面的segment轮训的分配到当前的各个undo tablespace

初始化的时候会计算undo space id，然后根据不同undo space id初始化undo segment，5.7分配代码：

trx_sys_create_rsegs

for (i = 0; i < new_rsegs; ++i) { //对每个rollback segment进行初始化
            ulint   space_id;
            space_id = (n_spaces == 0) ? 0
                : (srv_undo_space_id_start + i % n_spaces); 
//获取 undo space_id 采用取模的方式循环
 //如果是2个undo tablespace，则space 为1,2,1,2
            ut_ad(n_spaces == 0
                  || srv_is_undo_tablespace(space_id));

            if (trx_rseg_create(space_id, 0) != NULL) {
                ++n_used;
                ++n_redo_active;

使用的时候也是进行轮询使用每个segment，5.7使用segment部分

get_next_redo_rseg:

static ulint    redo_rseg_slot = 0; //此处是静态变量
slot = redo_rseg_slot++; //静态变量，不断轮训使用
slot = slot % max_undo_logs;//取模轮询使用
...

           else if (rseg->skip_allocation) { 
//skip_allocation为purge线程做truncate undo tablespace的时候设置
                ut_ad(n_tablespaces > 1); 
//如果是skip_allocation 很明显不能是单个undo tablespace,需要断言大于1
                ut_ad(max_undo_logs
                    >= (1 + srv_tmp_undo_logs + 2));
                continue;

这里如果undo segment处于skip_allocation状态不能分配，这个值则由我们的purge线程做truncate undo tablespace的时候设置。

查看数据库的undo目录下有类似文件（测试）

image.png

三、 purge线程truncate undo tablespace

undo的truncate 由purge线程在做完undo的回收后(物理空间不变)后，回收的时候当前也需要判断当前的undo是否需要才可以回收。然后通过设置的参数和当前undo物理文件的大小进行循环判断，并且如果有活跃事务持有本undo segment则不能truncate。

trx_purge_truncate_history末尾：
for (i = 0; i < nchances; i++) {
//每次循环判断一个 undo tablespace
        trx_purge_mark_undo_for_truncate(&purge_sys->undo_trunc);
 //判断本undo tablespace是否可以truncate，
//如果需要清理标记为rseg->skip_allocation = true，不在分配本undo segment。
        trx_purge_initiate_truncate(limit, &purge_sys->undo_trunc); 
//进行undo tablespace的清理 。
    }


以下为判断是否查过参数innodb_max_undo_log_size设置的逻辑
if (fil_space_get_size(space_id)
            > (srv_max_undo_log_size / srv_page_size)) {
//srv_max_undo_log_size为参数innodb_max_undo_log_size的设置大小
            /* Tablespace qualifies for truncate. */
            undo_trunc->mark(space_id); 
//标记为需要 truncate
            undo::Truncate::add_space_to_trunc_list(space_id); 
//插入到truncate 列表
            break;
        }

truncate的步骤比较多。在清理的最后会做如下步骤：

    a. log-checkpoint
    b. Write the DDL log to protect truncate action from CRASH
    c. Remove rseg instance if added to purge queue before we
       initiate truncate.
    d. Execute actual truncate
    e. Remove the DDL log.

而我们的undo_trunc.log正是DDL log这样一个文件，因此只要它存在则说明undo tablespace的tunracte没有正常结束。

四、如何模拟

这个问题已经有朋友提交了bug
https://bugs.mysql.com/bug.php?id=104573

我的测试方法如下，选择版本MySQL8.0.27，也就是最新版本，我们发现BUG依旧存在。

选择MGR的一个备份节点，首先需要设置参数
set global innodb_max_undo_log_size=11534336;
set global innodb_purge_rseg_truncate_frequency=1;

其中innodb_purge_rseg_truncate_frequency默认为128。如果调为1会加大undo清理和truncate判断的频率。
参数影响如下：

这个和参数innodb_purge_rseg_truncate_frequency的设置有关，默认为128，如果满负荷计算为 ：

300(undo log pages)*128(truncate frequency ) = 38,400
38400个undo log pages处理完成后会进行一次undo history清理。

根据参数赋值
set_rseg_truncate_frequency(
        static_cast<ulint>(srv_purge_rseg_truncate_frequency));

参数判断
    ulint rseg_truncate_frequency = ut_min(
        static_cast<ulint>(srv_purge_rseg_truncate_frequency), undo_trunc_freq); //128

    n_pages_purged = trx_purge(n_use_threads, srv_purge_batch_size,
                               (++count % rseg_truncate_frequency) == 0);//每128次进行一次清理

判断是否进入truncate流程
  if (truncate || srv_upgrade_old_undo_found) { //truncate就是根据(++count % rseg_truncate_frequency)计算而来
    trx_purge_truncate();
  }

但是需要注意的count是一个static局部变量，因此每次调入函数会继续上次的取值继续计数。如果压力很小那么undo可能不能及时清理：

小事务
如果都是小事务那么每个事务修改的undo page数可能达不到300个，那么必然需要等待128个事务才能进行一次清理。

大事务
如果事务比较大，有许多undo page，那么超过了300*128 那么就会进行清理。

这不是说del flag记录不清理，而是说undo history链表不清理。因此我们经常看到History list length不为0的情况。

注意线上不要设置innodb_purge_rseg_truncate_frequency=1，否则会导致purge线程的CPU负载飙升

在备节点选择一张表，做一个大查询

select sleep(10000) from test;

这样做的目的是为了积压UNDO不会及时清理掉。

使用sysbench加压主节点
观测从节点undo空间大小
一旦从节点的undo 空间增大，就可以中止结束大查询，这样就是放了read view，undo可以清理
对清理接口进行DEBUG

五、问题触发点和相关BUG

我们发现出问题的栈如下，实际上是在修改tablespace_files和tablespaces两个字典的时候，检测发现为read only，因此出现了问题。

#0  lock_tables_check (thd=0x7fff44001110, tables=0x7fff06ffb600, count=2, flags=18434) at /newdata/mysql-8.0.27/sql/lock.cc:214
#1  0x000000000385bee7 in mysql_lock_tables (thd=0x7fff44001110, tables=0x7fff06ffb600, count=2, flags=18434) at /newdata/mysql-8.0.27/sql/lock.cc:325
#2  0x00000000031b1e20 in lock_dictionary_tables (thd=0x7fff44001110, tables=0x7fff44098328, count=2, flags=18434) at /newdata/mysql-8.0.27/sql/sql_base.cc:7050
#3  0x000000000478e882 in dd::Open_dictionary_tables_ctx::open_tables (this=0x7fff06ffb750) at /newdata/mysql-8.0.27/sql/dd/impl/transaction_impl.cc:124
#4  0x000000000469dc95 in dd::cache::Storage_adapter::store<dd::Tablespace> (thd=0x7fff44001110, object=0x7fff4405f3e0) at /newdata/mysql-8.0.27/sql/dd/impl/cache/storage_adapter.cc:334
#5  0x00000000045acc35 in dd::cache::Dictionary_client::update<dd::Tablespace> (this=0x7fff44000bf0, new_object=0x7fff4405f3e0)
    at /newdata/mysql-8.0.27/sql/dd/impl/cache/dictionary_client.cc:2653
#6  0x0000000004565cfd in dd::commit_or_rollback_tablespace_change (thd=0x7fff44001110, space=0x7fff4405f3e0, error=false, release_mdl_on_commit_only=false)
    at /newdata/mysql-8.0.27/sql/dd/impl/dictionary_impl.cc:721
#7  0x0000000004d9a492 in dd_tablespace_set_id_and_state (space_name=0x7fff44058a88 "innodb_undo_001", space_id=4294966898, state=DD_SPACE_STATE_ACTIVE)
    at /newdata/mysql-8.0.27/storage/innobase/dict/dict0dd.cc:5997
#8  0x0000000004bceea2 in trx_purge_truncate_marked_undo_low (space_num=1, space_name=...) at /newdata/mysql-8.0.27/storage/innobase/trx/trx0purge.cc:1496
#9  0x0000000004bcf262 in trx_purge_truncate_marked_undo () at /newdata/mysql-8.0.27/storage/innobase/trx/trx0purge.cc:1560
#10 0x0000000004bcf942 in trx_purge_truncate_undo_spaces () at /newdata/mysql-8.0.27/storage/innobase/trx/trx0purge.cc:1691
#11 0x0000000004bd1535 in trx_purge_truncate () at /newdata/mysql-8.0.27/storage/innobase/trx/trx0purge.cc:2395
#12 0x0000000004bd19f1 in trx_purge (n_purge_threads=4, batch_size=300, truncate=true) at /newdata/mysql-8.0.27/storage/innobase/trx/trx0purge.cc:2501
#13 0x0000000004b7d539 in srv_do_purge (n_total_purged=0x7fff06ffca70) at /newdata/mysql-8.0.27/storage/innobase/srv/srv0srv.cc:2924

lock_tables_check 会根据read only进行判断，如下：

    /*
      Prevent modifications to base tables if READ_ONLY is activated.
      In any case, read only does not apply to temporary tables and
      performance_schema tables.
    */
    if (!(flags & MYSQL_LOCK_IGNORE_GLOBAL_READ_ONLY) && !t->s->tmp_table &&
        !is_perfschema_db(t->s->db.str, t->s->db.length)) { //flags没有忽略read only
      if (t->reginfo.lock_type >= TL_WRITE_ALLOW_WRITE &&
          (check_readonly(thd, true) ||
           check_schema_readonly(thd, t->s->db.str, t->s))) {
        return 1;//这里返回1
      }
    }

这里flags为:0100100000000010 (18434)
MYSQL_LOCK_IGNORE_GLOBAL_READ_ONLY为:1000
因此条件flags & MYSQL_LOCK_IGNORE_GLOBAL_READ_ONLY条件返回为false，取反后为true，触发了readonly检测。接下来分析出来 dd::commit_or_rollback_tablespace_change在这种场景下没有忽略read only 去做的提交如下：

trans_commit(THD *thd, bool ignore_global_read_lock)

因此从整个问题来看，还是在这种特殊的场景下没有考虑到read only的存在，主要存在于2点：

修改数据字典（dd::Open_dictionary_tables_ctx::open_tables）
修改字典的事务提交（dd::commit_or_rollback_tablespace_change）

因此在truncate tablespace的最后导致了错误，但是实际的truncate任务（重建文件）已经完成了。但是由于报错导致没有跑到删除DDL log的流程。而我们的xtrbackup刚好是检测了DDL log这个地方，来确定undo是否处于重建状态。这里已经有朋友提交了BUG如下：
https://bugs.mysql.com/bug.php?id=104573

六、规避方法和其他

当然这个已经有朋友提到了：

加大undo tablespace的大小，这样自然不会触发truncate条件，如果不触发truncate那么自然没有DDL log。
减少大事务，减少大查询，这样undo segment在回收完会重新使用，不会继续扩张undo tablespace大小。
等待官方修复

其实在整个初始化和分配过程中，我们已经发现事务的undo实际上是分布在不同的undo tablespace中的，并不是先用一个undo tablespace，等到需要切换的时候才进行使用另外一个，因此遇到大查询（长时间的查询）这种情况，各个undo的大小也是比较均匀的增长的。
其次因为这种轮询分配的方式，让purge线程有机会进行truncate操作，只是在做truncate之前标记本undo tablespace上的undo segment不可用就好了。

xtrbackup:Cannot recover a trunc

一、 xtrbackup的报错

二、 undo的segment初始化和使用

三、 purge线程truncate undo tablespace

四、如何模拟

五、问题触发点和相关BUG

六、规避方法和其他

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

xtrbackup:Cannot recover a trunc

一、 xtrbackup的报错

二、 undo的segment初始化和使用

三、 purge线程truncate undo tablespace

四、 如何模拟

五、问题触发点和相关BUG

六、 规避方法和其他

相关文章

网友评论

延伸阅读

深度阅读

栏目导航

热点阅读

四、如何模拟

六、规避方法和其他