rocksdb生成快照慢问题定位

0. 背景描述

测试 rocksdb 多副本版的导入时发现 rocksdb 生成快照非常慢,其实一开始还发现了一些别的影响导入的因素,但都不是最核心的问题,这里就不说了。

我们直奔主题,具体执行慢的代码位于RocksDBStore类的writeSnapshot方法(下称写快照或生成快照):

@Override
public void writeSnapshot(String parentPath) {
    Lock writeLock = this.storeLock.writeLock();
    writeLock.lock();
    try {
        LOG.info("Store {} prepare write snapshot", this.store);
        // Every rocksdb instance should create an snapshot
        for (RocksDBSessions sessions : this.sessions()) {
            sessions.createSnapshot(parentPath);
        }
        LOG.info("Store {} write snapshot succeed, store lock will release",
                 this.store);
    } finally {
        writeLock.unlock();
    }
}

sessions.createSnapshot方法里最主要的代码是调 rocksdb 提供的checkpoint.createCheckpoint(tempPath)方法,这个方法是干什么的下面会说明。

测试发现,导入20分钟的数据后,进行一次写快照,需要两分半钟,在此期间,storeLock的写锁一直未释放,导致上层所有的读写请求都被阻塞,服务处于不可用状态。

1. 定位问题

1.1 查看官方文档

首先肯定是看一下官方文档,看我使用得对不对。checkpoint 的链接: https://github.com/facebook/rocksdb/wiki/Checkpoints

文档里面说了几个点:

  1. checkpoint 是 rocksdb 提供的一个为运行中的 db 生成快照的特性;
  2. 用 checkpoint 生成的快照,可以以只读方式或读写方式打开;
  3. checkpoint 机制可用于全量备份和增量备份;
  4. 需要指定一个目录存放快照;
  5. 如果快照目录与原始数据文件位于同一文件系统上,SST 文件将被硬链接,否则 SST 文件将被复制;
  6. manifest 和 CURRENT 文件会被复制;
  7. 如果有多个列族,则会复制 checkpoint 开始和结束期间的日志文件(应该是 wal)。

这里的一个关键点是:如果位于同一文件系统上,sst 文件将被硬链接,所以应该是一个非常快速的操作,为什么实际测起来那么慢呢?

从这里似乎看不出什么问题,因为我也提供了目录,而且这个目录的文件系统与原始数据的文件系统是一样的。

看来得使用老套路——火焰图帮忙分析了。

1.2 打火焰图

为了更方便地打火焰图,其实我改了一下代码,为 Graph 增加了一个显式生成快照的方法,这样就不用非要等 raft 的快照机制触发了,我可以自行控制生成快照的时机。当然,这只是辅助测试的修改,代码就不贴了。

替换 jar 包,启动服务(此前已经保存了 150G 的数据了)后,请求 API 主动生成快照,然后用 arthas 工具生成了火焰图:

生成快照.png

从火焰图中可以看到,有大量的entry_SYSCALL_64_fastpathvfs_readvfs_write系统调用。很明显,这是我看不懂的东西,但是看名字大概能猜到:这是在读写虚拟文件系统,而且能看到一个rocksdb::CopyFile的方法调用占了很大比例。按道理,创建硬连接应该跟这些readwriteCopy是无关的。

所以:猜测这应该不是生成硬链接,而是在复制文件。

虽然看不懂这些系统调用,好在火焰图也打印了 rocksdb 的方法调用:CreateCustomCheckpoint,所以跟踪一下 rocksdb 的源码吧。

1.3 查看 rocksdb 源码

rocksdb/utilities/checkpoint/checkpoint_impl.cc中搜到了CreateCustomCheckpoint方法,方法签名如下:

// 方法签名
Status CheckpointImpl::CreateCustomCheckpoint(
    const DBOptions& db_options,
    std::function<Status(const std::string& src_dirname,
                         const std::string& src_fname, FileType type)>
        link_file_cb,
    std::function<Status(
        const std::string& src_dirname, const std::string& src_fname,
        uint64_t size_limit_bytes, FileType type,
        const std::string& checksum_func_name, const std::string& checksum_val)>
        copy_file_cb,
    std::function<Status(const std::string& fname, const std::string& contents,
                         FileType type)>
        create_file_cb,
    uint64_t* sequence_number, uint64_t log_size_for_flush,
    bool get_live_table_checksum) {

其接受了 3 个 function 参数比较令人注意,分别表示链接文件拷贝文件创建文件的函数,所以可以大胆猜测,方法里面的逻辑是:先判断能不能链接文件,如果不行就拷贝文件,再不行就创建文件。

再继续往下看主逻辑,果然看到了符合猜想的代码:

// rules:
// * for kTableFile, attempt hard link instead of copy.
// * but can't hard link across filesystems.
if (same_fs) {
  s = link_file_cb(db_->GetName(), src_fname, kTableFile);
  if (s.IsNotSupported()) {
    same_fs = false;
    s = Status::OK();
  }
}
if (!same_fs) {
  // 省略
  s = copy_file_cb(db_->GetName(), src_fname, 0, kTableFile, checksum_name,
                   checksum_value);
}

链接文件和拷贝文件的比较顺序是符合猜想的,不过创建文件只是跟 manifest 和 CURRENT 有关的。

上述代码的逻辑是:如果是相同的文件系统,就执行链接,链接的 function 如果返回“不支持”,就执行拷贝。

根据火焰图的方法占比推断,就是执行了上述的逻辑。那现在的问题是:为什么链接文件会报“不支持”。

继续回过头查看调用CreateCustomCheckpoint的地方,看看link_file_cb是怎么定义的:

s = CreateCustomCheckpoint(
    db_options,
    // 这就是 link_file_cb 函数的定义
    [&](const std::string& src_dirname, const std::string& fname, FileType) {
        ROCKS_LOG_INFO(db_options.info_log, "Hard Linking %s", fname.c_str());
        return db_->GetFileSystem()->LinkFile(src_dirname + fname,
                                              full_private_path + fname,
                                              IOOptions(), nullptr);
    } /* link_file_cb */,
    [&](const std::string& src_dirname, const std::string& fname,
        uint64_t size_limit_bytes, FileType,
        const std::string& /* checksum_func_name */,
        const std::string& /* checksum_val */) {
        ROCKS_LOG_INFO(db_options.info_log, "Copying %s", fname.c_str());
        return CopyFile(db_->GetFileSystem(), src_dirname + fname,
                        full_private_path + fname, size_limit_bytes,
                        db_options.use_fsync);
    } /* copy_file_cb */,
    [&](const std::string& fname, const std::string& contents, FileType) {
        ROCKS_LOG_INFO(db_options.info_log, "Creating %s", fname.c_str());
        return CreateFile(db_->GetFileSystem(), full_private_path + fname,
                          contents, db_options.use_fsync);
    } /* create_file_cb */,
    &sequence_number, 
    log_size_for_flush);

这里看到了link_file_cbcopy_file_cb的定义,我们发现在函数内部,其实都有日志打印的。这个日志会打印到哪呢?rocksdb 数据目录下的 LOG 文件。查看 LOG 文件,果然搜索到了如下内容:

2021/02/04-15:32:37.140621 7fd652cec700 [/db_filesnapshot.cc:30] File Deletions Disabled
2021/02/04-15:32:37.146337 7fd652cec700 [ilities/checkpoint/checkpoint_impl.cc:115] Hard Linking /009366.sst
2021/02/04-15:32:37.146354 7fd652cec700 [ilities/checkpoint/checkpoint_impl.cc:122] Copying /009366.sst
2021/02/04-15:32:39.840758 7fd652cec700 [ilities/checkpoint/checkpoint_impl.cc:122] Copying /009362.sst
2021/02/04-15:32:40.257284 7fd652cec700 [ilities/checkpoint/checkpoint_impl.cc:122] Copying /009376.sst
2021/02/04-15:32:42.986539 7fd652cec700 [ilities/checkpoint/checkpoint_impl.cc:122] Copying /009380.sst

现在就确认了前面的猜想,确实是先尝试链接文件,然后失败,于是走了拷贝文件的分支。

但是疑惑点还是存在:明明是同一个机器,为什么链接会失败呢?要不直接用 linux 命令验证一下吧。

1.4 命令验证

在我当前的目录执行 ln 命令创建硬链接:

$ ln /home/disk1/rocksdb-vertex/g/009366.sst hard-link.sst
ln: creating hard link `hard-link.sst' => `/home/disk1/rocksdb-vertex/g/009366.sst': Invalid cross-device link

居然报了Invalid cross-device link,不能跨设备链接。

是用命令查看磁盘和目录的对应关系:

$ df -h
Filesystem            Size  Used Avail Use% Mounted on
/dev/sda2              19G  4.8G   14G  27% /
tmpfs                  63G   11M   63G   1% /dev/shm
/dev/sda3              14G  457M   14G   4% /var
/dev/sda4              14G  939M   13G   7% /noah
/dev/sda5             4.6G  509M  4.1G  12% /matrix
/dev/sda6             1.9G  294M  1.6G  16% /has
/dev/sda7             6.4G  2.1G  4.3G  33% /tmp
/dev/sda8             2.6T  1.8T  852G  68% /home
/dev/sdb1             2.7T  622G  2.0T  25% /home/disk1
/dev/sdc1             2.7T  787G  1.8T  31% /home/disk2
/dev/sdd1             2.7T  500G  2.2T  19% /home/disk3

猛然想起来,当前所在的目录(/home/xxx)和原始数据的目录(/home/disk1)属于不同磁盘,这就是硬链接失败的原因。

2. 修复问题

知道了问题原因是:快照目录和原始数据目录不在同一块盘,改就好改了,让快照目录与原始数据目录位于同一块盘即可。

TODO: 附上 pr 链接

3. 总结

其实回过头来想想,其实好多地方都有迹象表明这个问题的原因是什么,比如:

  1. 直接查看 rocksdb 的 LOG 文件,能看到大段的 Copying 字样;
  2. 查看原始文件和快照文件的详细信息,对比 inode,会发现不一样;
  3. 直接敲一下 ln 命令,就能看到异常提示信息;

未能快速发现问题,主要还是因为对 linux 系统不太熟悉所致,以后需要在这方面加强一下。

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

推荐阅读更多精彩内容