Gitlab

记一次Gitlab-Runner卡顿的详情分析

Posted by 刘勇(lyonger) on 2019-11-27

记一次Gitlab Runner卡顿的详情分析

  • 该问题排查耗时数周，下面分享一下整体的排查过程，仅供大家参考。

问题的背景

  • 最近Gitlab Runner服务偶尔接到用户反馈build超时和卡顿。下面是某个用户提供的问题截图。比如build超时：

    20190906103356

  • 用户反馈卡顿，比如：

20190711170145

  • 由于该问题具有普遍性，不同的用户在不同的repo进行ci均会偶发性产生问题，于是着手做一次深入的排查。

故障机器的配置说明

  • 机器为KVM虚拟机，配置如下。
1
2
3
4
5
系统版本：Debian9.7
内核版本：4.9.0-8-amd64
CPU核数：16
内存大小：16GB
磁盘大小：300G sas

故障的分析详情

第一次排查

  • 在初次遇到这个问题结合用户反馈的截图，怀疑看docker.sock不响应。所以，当时尝试在事故发生现场，努力的strace追踪docker.sock的系统调用情况，下面是某次现场分析的截图，发现请求socket确实会有卡住的现象。然而这一次过了以后，没有深入找到原因，因为现场没有保存。下面是故障时的strace截图。

    20190711162549

第二次排查

  • 接着某天再此收到用户报障，这次又深入了一点，找到了系统层的CPU异常，且IO使用率高。在这里看到cpu的st占用高，就怀疑是虚拟机的资源复用太严重，所以就让同事把这台机器迁移到了独占宿主机，目的是排除CPU的影响。其实这里忽略了io高的原因，当时被st高的现象给迷惑了。

    • 系统top分析截图
      image

    • io监控图数据
      20190711162750

第三次排查

  • 迁移了宿主以后，发现没过几天又接到用户的报障。由于已经排除了CPU的影响。思路就集中在了其他资源上，这次定位发现系统io存在可疑，如下图：

    • 系统整体使用情况
      20190711163615

    • iotop定位到loop内核线程io高，其实内核线程的祖先是pid为2的kthreadd进程。
      20190711163639

    • loop内核线程确实有读发生，且在进程分布中读的量最大。
      20190711163653

  • 到了第三次排查，大概定位到了瓶颈为loop内核线程，但是loop内核线程到底在做什么事情呢，这个问题值得思考，读到这里，您会有哪些思考呢？其实要知道内核线程具体的内部调用栈情况，需要使用到动态追踪工具，那业界优秀的动态追踪工具有哪些呢？下文就为你揭晓答案。

第四次排查

  • 这一次排查使用perf工具保存了现场，并利用perf保存的数据生成了火焰图，定位到热点函数是loop_queue_work，其对应的内核源码定义如下
    20190711164039
  • 从perf火焰图可知，热点函数是loop_queue_work。这里普及一下火焰图的查看技巧，火焰图一般是从下往上看，横轴表示采样数和采样比例，一个函数占用的横轴越宽就代表它的执行时间越长。纵轴表示调用栈，上下相邻的2个函数中，下面的函数是上面函数的父函数。
    20190711164058
  • 从热点函数名中可知，含有队列(queue)2个字，于是想到了磁盘调度算法，接着尝试调整虚拟机的磁盘调度算法。发现虚拟机使用了Ceph RBD磁盘，不支持修改磁盘调度算法。于是这里卡住了继续下一步的线索。
    20190906104158

第五次排查

  • 在这一次排查中，终于拨开了迷雾。在一次偶然的机会，有一个用户提供了一个和前几次不一样的报错截图，如下图：
    20190906104312

  • 排查到gitlab runner机器上的devmapper存储驱动目录确实挺大，但是为啥镜像清理了以后，空间依旧没释放呢。于是网上查了一番，发现这个存储驱动已经不推荐使用了，有性能问题。关于Docker如何选择存储驱动，请参考这里。
    20190906104436

  • 至于我们这里为什么有使用devmapper这个驱动，是因为在一次升级系统内核时做的变更导致。我们查看到线上docker运行到存储驱动正是devmapper。
    20190906104813

  • 这一次机智的用perf保存了现场，再次分析热点函数，看到和xfs文件系统相关。
    20190711164939

  • 在2个月前升级系统内核时，由于在xfs文件系统下没有打开下面这个选项（ftype=1才代表打开）导致只能使用devmapper驱动。从这里再联想到热点函数也是显示xfs文件系统相关，不得不考虑是存储驱动导致的性能问题了。
    20190906104929

  • 在没有打开这个选项(ftype=1）的情况下使用overlay存储驱动会报错如下：
1
could not use snapshotter overlayfs in metadata plugin" error="/home/gitlab/var/lib/docker/containerd/daemon/io.containerd.snapshotter.v1.overlayfs does not support d_type. If the backing filesystem is xfs, please reformat with ftype=1 to enable d_type support

  • 而Docker有在源码里面也有定义使用的存储驱动优先级。
    20190711165321

  • 于是备份数据后使用mkfs.xfs -n ftype=1 /dev/vdc1命令重新格式化磁盘，打开ftype选项。接着强制配置Docker进程使用overlay2的存储驱动，再次模拟用户触发ci任务，观察发现loop内核线程不会有io产生。整个系统的io也降低了。再更改回devmapper以后，loop内核线程又变高了，由此定位到了最终问题。

自测结果

  • 下面是使用同一个repo，在同一个gitlab站点测试使用devmapper和overlay2不同存储驱动的表现情况。

    • 使用overlay2存储驱动的io数据
      20190711171200
      20190711195249

    • 使用iotop看不到loop内核线程有io情况，更不会排在首位。
      20190711171422

    • 使用devmapper存储驱动的io数据
      20190711171308
      20190711195347

    • 使用iotop查看到loop内核线程io消耗且排在了首位。
      20190711171435

思路总结

  • 从这一次的故障诊断分析来看，耗时较久，从一开始的现象到最终的分析，都是逐步进行的。故障发生的时刻往往短暂，所以想办法保存现场数据或者复现故障显得尤为重要。对于性能优化，基本是长期跟踪，动态调整，大部分的分析是从系统到进程或者线程，再到内核热点函数，再到操作系统原理。 最后期待本文能对你以后的故障排查提供帮助，知识在于分享，更希望你可以把此文分享给你的朋友。

资料参考

推荐阅读


赏 支付宝打赏 微信打赏

赞赏一下



FEATURED TAGS
Gitlab
FRIENDS