xtrbackup:Cannot recover a truncated undo tablespace in read-only mode


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


一、 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不可用就好了。

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 216,163评论 6 498
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 92,301评论 3 392
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 162,089评论 0 352
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 58,093评论 1 292
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 67,110评论 6 388
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 51,079评论 1 295
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 40,005评论 3 417
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 38,840评论 0 273
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 45,278评论 1 310
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 37,497评论 2 332
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 39,667评论 1 348
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 35,394评论 5 343
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 40,980评论 3 325
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 31,628评论 0 21
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 32,796评论 1 268
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 47,649评论 2 368
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 44,548评论 2 352

推荐阅读更多精彩内容