任务执行龟速，原因竟然是......
介绍在 k8s 环境中一次任务执行龟速的排查过程
问题背景
某天，业务同学反馈生产环境k8s集群中由核心服务创建的Job任务执行速度奇慢......
通过分析服务日志发现，该服务运行前期主要是执行请求数据交换服务，获取到oss对象存储的文件url后进行下载，下载完成后再执行其他任务
分析和复盘
“服务好好的，怎么用着用着就慢了呢？” 旁边的xx开始发起了灵魂拷问
由于此问题偏故障型，首先想到的当然是秉承着“有报错，看日志”的宗旨，去看各方服务的日志
通过排查日志，均无错误，但现象就是日志慢而且卡顿
于是先判断是不是服务之间的网络出问题了
简单思考了下，与网络因素相关，再加上排除法，最小化可能的相关原因有如下
pod网卡- 节点和
pod网络检查 - 调度到不同节点的网卡对比
- 不同场景下网卡出入站带宽
dns解析- 节点资源综合对比
oss服务端限流等策略核查- 服务本身代码是否变更等等
对照可能 原因开始一一排查，如下列举一些相关的具体排查方法，其余就不再赘述了
网络带宽测试
对于网络带宽的测试，可以选用ethtool、iperf等工具，可以很方便的帮我们查看网卡相关信息，测试网络出站入站的带宽，顺便加上抓包工具
# ethtool
Settings for eth0:
Supported ports: [ ]
Supported link modes: Not reported
Supported pause frame use: No
Supports auto-negotiation: No
Advertised link modes: Not reported
Advertised pause frame use: No
Advertised auto-negotiation: No
Speed: 10000Mb/s
Duplex: Full
Port: Twisted Pair
PHYAD: 0
Transceiver: internal
Auto-negotiation: off
MDI-X: Unknown
Cannot get wake-on-lan settings: Operation not permitted
Link detected: yes
# iperf
Server listening on TCP port 5001
TCP window size: 12.0 MByte (default)
------------------------------------------------------------
[ 4] local 10.244.155.34 port 5001 connected with 10.244.0.196 port 42148
[ ID] Interval Transfer Bandwidth
[ 4] 0.0000-2.0000 sec 1.62 GBytes 6.97 Gbits/sec
[ 4] 2.0000-4.0000 sec 1.15 GBytes 4.93 Gbits/sec
[ 4] 4.0000-6.0000 sec 1.15 GBytes 4.93 Gbits/sec
[ 4] 6.0000-8.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 8.0000-10.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 10.0000-12.0000 sec 1.14 GBytes 4.92 Gbits/sec
[ 4] 12.0000-14.0000 sec 1.14 GBytes 4.89 Gbits/sec
[ 4] 14.0000-16.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 16.0000-18.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 18.0000-20.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 20.0000-22.0000 sec 1.14 GBytes 4.89 Gbits/sec
[ 4] 22.0000-24.0000 sec 1.14 GBytes 4.89 Gbits/sec
[ 4] 24.0000-26.0000 sec 1.13 GBytes 4.87 Gbits/sec
[ 4] 26.0000-28.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 28.0000-30.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 30.0000-32.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 32.0000-34.0000 sec 1.14 GBytes 4.89 Gbits/sec
[ 4] 34.0000-36.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 36.0000-38.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 38.0000-40.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 40.0000-42.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 42.0000-44.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 44.0000-46.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 46.0000-48.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 48.0000-50.0000 sec 1.15 GBytes 4.93 Gbits/sec
[ 4] 50.0000-52.0000 sec 1.14 GBytes 4.91 Gbits/sec
[ 4] 52.0000-54.0000 sec 1.14 GBytes 4.92 Gbits/sec
[ 4] 54.0000-56.0000 sec 1.14 GBytes 4.90 Gbits/sec
[ 4] 56.0000-58.0000 sec 1.14 GBytes 4.88 Gbits/sec
[ 4] 58.0000-60.0000 sec 1.14 GBytes 4.89 Gbits/sec
[ 4] 60.0000-60.0201 sec 13.6 MBytes 5.69 Gbits/sec
[ 4] 0.0000-60.0201 sec 34.7 GBytes 4.97 Gbits/sec
结果：无果
dns解析测试
对于dns解析的测试，利用dig、nslookup工具分别选取了公网域名，内网域名，集群内域名分别测试进行对比，例如
www.baidu.com
data.ssgeek.com
data-download.default.svc.cluster.local
结果：无果
业务代码排查
针对于此业务，排查了其发布的版本，在出故障时并未发布新版本
服务是python语言写的，于是结合sdk对代码进行分析，将oss下载相关逻辑拆分出来，写成python脚本，单独调用sdk获得下载地址，然后进行下载流程，分别计算每一步骤执行的时间
结果：无果
多方对比法
4.1 基础镜像
由于有同类以deployment形式部署的对应服务，但在deployment的pod中下载没有任何问题
代码一样，开始怀疑是否因job任务使用的镜像与正常的镜像底层有关系
分别检查了对应的Dockerfile，发现base镜像及版本都不一样
于是将其变为同样的base镜像再次对比，任务执行时间还是有很大区别
结果：无果
4.2 下载外网文件
排除了镜像问题，继续排除oss服务端的问题，于是分别通过shell让两边的pod去公网下载同样的大文件以及同样的小文件分别进行对比
结果：无果
到这里已经近乎mb了
这里也省略其他对比的一些措施
直接下载测试
通过上面的一些sao操作，发现都没有明显效果，这对问题的排查增加了一定难度
于是乎，能不能抛开代码业务逻辑不谈，先一次性拿到所有需要下载文件的地址，然后手动通过原始的shell脚本去批量执行下载任务进行对比呢？当然
这里举例，用shell下载文件的脚本如下
#/bin/bash
j=1
for i in `cat 1.txt`
do
echo $j
curl -s -o $j.jpg $i
let j=j+1
done
# txt为文件的url列表
问题定位
通过上面最后一次通过shell脚本下载文件测试时发现：
在测试脚本刚开始启动时，程序会停顿几分钟，然后再开始执行下载任务，这意味着bash程序启动慢
换做job，job运行的pod执行的是一次性任务，因此和脚本执行是一样的，只是k8s层提供了这个脚本执行的载体，即pod
我们可以用一个简单的命令组合，检查当前bash的执行时间，发现相比正常情况下要慢很多
# time bash -c exit
real 0m0.004s
user 0m0.000s
sys 0m0.000s
问题分析
通过进一步检查程序启动慢的资料发现，程序在启动之前往往会加载系统的环境变量
由于pod执行的是一次性任务，因此这种job的执行时间就包含了
- 加载环境变量的时间
- 程序执行时间（包含网络请求、
io读写、计算等）
而普通的pod，在正常运行第一次启动时就已经加载了环境变量，所以当pod再次去执行某些任务时，已经不需要这一步骤了 ~
这样一来，当环境变量过多时，程序启动就会变慢
通过env命令，可以打印出pod内所有的环境变量
默认情况下k8s会为每个pod都注入除了自定义的环境变量以外的，这个pod所在命名空间下所有的公共环境变量
到这里，事情开始出现了转机，于是默默兴奋了一把
于是计算了一下环境变量个数，竟然高达35000+个环境变量，进一步排查发现，几乎99%的环境变量都是一个大量任务的相关服务的环境变量，这个服务会以deployment、service的命名不同，来创建很多个定义一样，命名不同的副本服务，进一步在集群中检查，此类服务的数量达4500多个
在谷歌Google Kubernetes Engine (GKE)中建议
每个命名空间的Service数不应超过5000。如超过此值，Service环境变量的数量会超出shell限制，导致Pod在启动时变慢甚至崩溃。在Kubernetes 1.13版本后，可以通过将PodSpec中的enableServiceLinks设置为false来停止填充这些变量
这个值在阿里云Alibaba Cloud Container Service for Kubernetes (ACK)的默认建议是1000个
即想要禁止注入无关环境变量的注入，从Kubernetes 1.13版本开始，可以声明enableServiceLinks: false
更巧的是，默认创建的pod，这个enableServiceLinks选项是不可见（隐式）的，即使-o yaml也不会输出，但是默认值又给了true，这就让人很难察觉了
源码部分参考
pkg/apis/core/v1/defaults.go
if obj.Spec.EnableServiceLinks == nil {
enableServiceLinks := v1.DefaultEnableServiceLinks
obj.Spec.EnableServiceLinks = &enableServiceLinks
}
k8s.io/api/core/v1/types.go
const (
// The default value for enableServiceLinks attribute.
DefaultEnableServiceLinks = true
)
问题解决
最终通过在job的定义中添加了这个参数的默认值，新创建的pod的就仅剩不到30个环境变量
修改创建job的相关代码job_scheduler.go
var (
...
jobTaskK8sEnableServiceLinks = false
)
...
targetJob.Spec.Template.Spec.EnableServiceLinks = &jobTaskK8sEnableServiceLinks
...
再次部署新的服务并在相同场景下测试，下载速度恢复如常，问题得以解决~
小结
小结一下，本文记录复盘的是一次k8s集群相关的生产故障
随着服务增多，集群的庞大，一些未知问题就必然会出现（而如果集群规模较小，也就基本不会遇到了）
对于一开始未知原因、诡异、没有思路的问题或者bug，往往利用穷举法列出所有可能的原因，然后采取最小化复现、差异化对比等等，基本能解决大部分这类问题
参考