kubernetes – 滚动发布引发调用方超时的新问题与定位

kubernetes集群的网络问题已经解决的差不多了,业务方也稳定的使用了一阵子了。

可惜最近两天,滚动发布又开始引发调用方超时了,这又是什么问题呢?

实际上,我们已经完美的实现了健康检查、优雅退出这些基本事项,也已经在线上平稳运行了好一阵子。

缩小范围

根据之前分析超时问题的经验,我首先通过单纯的扩容 or 单纯的缩容,明确是POD上线导致还是POD下线导致。

结果发现是POD下线导致的报错,也就是说流量可能被转给了下线中的POD。

然而这个问题我曾经已经解决过2次了,那2次的原因分别是:

  • kube-proxy ipvs模式的坑:ipvs本身有bug,转发规则在POD彻底删除前会令weight=0,此时会因为客户端源地址相同导致复用conntrack缓存关系,进而把流量再次送入到下线中的POD。(后来我们换了iptables就解决了)
  • kube-proxy规则同步慢:因K8S架构决定,当POD被标记terminating后,kubelet开始杀死POD和kube-proxy开始下线转发规则是同时进行的,因此如果kubelet先杀POD而Kube-proxy后下转发规则,则会导致流量被送入正在被杀死的POD。(后来我们在prestop中sleep 2秒来等待kube-proxy先下掉规则,问题得到解决)

如果上面2件事情你都做过了,还是报错,那么就是我这次遇到的第3个原因了。

初步怀疑

最近集群规模是变大了很多,100+node,2000+POD,因此iptables转发规则变多,导致了哪方面变慢了。

那么,此时有2个怀疑方向:

  • 因为规则多了,所以iptables-restore执行的时间太长了,之前给的sleep 2秒不够用了。
  • 因为集群node多了,所以etcd压力大了,同步到kube-proxy的延迟变高了。

为了观察这2个点,必须从k8s代码入手,看一下它们是否打印相关的时间点日志,以便来定位问题。

从K8S代码入手

具体看代码的过程我就不展开了,我分析了从deployment提交缩容变更之后的完整代码路径,得到如下的执行流程分析:

  1. 向apiserver提交deployment yaml进行缩容1次。
  2. deployment controller收到1次deployment变化event,向apiserver更新1次replicaset yaml。
  3. replicaset controller收到1次relicaset变化event,启动多个协程并发的向apiserver更新N个pod的status为terminating。
  4. endpoints controller收到N个pod变化event,对于每个pod event会根据内存反向索引反查pod属于哪个service,根据service label selector向apiserver筛选出pod list,同时再根据调用apiserver获取service name同名的endpoints对象,对比endpoints对象中现有pod ip list和本次筛选出的pod list是否有差异,没有则不会更新endpoints对象, 否则将最新pod ip list更新到endpoints对象的subsets字段,然后向apiserver提交endpoints对象。
  5. kube-proxy监听到endpoints对象变化,根据endpoints对象中记录的service name->pod ip list关系更新内存记录,并全量刷新iptables规则。
  6. kubelet监听到3)触发的pod更新event,则已经开始对变化POD进行退 出流程了,也就是先prestop hook,然后等待graceful terminating秒,之后强杀kill SIGKILL信号。

其实这里面的参与组件(进程)很多,包括:

  • apiserver:它封装了etcd的各类操作。
  • controller-manager:它实现了各种资源controller,比如replicaset、deployment、endpoints、service等等。
  • kube-proxy:它负责根据endpoints资源的变化,更新node上的iptables rules。
  • kubelet:它负责根据pod资源的变化,更新node上的docker container。

分析方法

通过代码,我找到了几个相关的日志,可以帮助我分析我的怀疑。

我能看到的几个重要信息是:

  • replicaset controller向apiserver并发更新N个POD的状态为terminating,一共花费了多久?
  • endpoints controller监听到上述POD的状态变化并更新endpoints,一共花费了多久?
  • endpoints更新事件,kube-proxy从apiserver同步到这个变化,一共花费了多久?
  • kube-proxy收到endpoints变化后,多久能完成iptables rules的刷新?

因此,我给kube-proxy、kubelet、controller-manager的启动参数分别配置了-v日志级别并重启,以便可以看到相关的日志。

在我打开日志的node上,实际观察了这些完整的路径:

replicaset几点删除了pod?

endpoints controller几点更新了endpoints?

kubelet几点开始POD退出流程?

kube-proxy几点同步到endpoints?

kube-proxy几点刷新完iptables规则?

然而发现好像也没有慢过2秒的。

iptables刷新规则虽然慢,但每次endpoints变化它会执行2次iptables-save和1次iptables-restore,也就200ms左右吧。

因为pod是并发更新的,因此endpoints controller虽然多次收到pod event,但是后面几次pod event其实去label selector筛选pod list已经没有diff了,因此也不会多次重复更新endpoints对象。

在实际日志中,我每次缩容时kube-proxy最差也就是收到2次endpoints更新事件,导致连续2次刷新iptables规则,也就花掉400ms,距离2秒还是很遥远的。

虽然做了很多分析,但是此时还是没有直观的证据来证明我的猜测。

再怀疑?

只能开始怀疑是不是自己运气不好,所在node同步是及时的,可能有其他node同步规则慢了?

实际上etcd压力并不大,很难怀疑etcd。

可是所有机器都开日志代价太高了,毕竟100+node,但是其他Node的嫌疑实在是无法忽略。

你必须付费加入我的知识星球,为有效知识付费是对作者最好的回报。

二维码见下方 或者 右侧边栏。

发表评论

电子邮件地址不会被公开。