Kubernetes 源码解读 - 由一次 debug 学到的

在最近公司办的第一次 Open L 活动中,我们分享了为什么我们要用 Kubernetes,其中吸引我们的一方面就是 autoscaling,它能够根据 CPU 等指标动态调整 pod 的个数,以此提高机器的利用率。

但最近却发现它并不能按预期正常地工作,deployment 的 Horizontal Pod Autoscaler(HPA) 显示的 CPU 并不能反应实际情况,所以也就不能正常地对 pod 的数量进行调整。查了 log 又 Google 一番后,我们并没有发现根本原因和解决办法,试了一些可能的方案,比如升级 docker,也没有解决,于是我们决定借助 k8s 的相关源码来弄清问题的根由,也方便之后再出现其他问题时能够更快地解决。

(本文基于 Kubernetes v1.4.6 e569a27d02 和 heapster v1.2.0 eea8c965)

先看一下 HPA 的工作原理:
Horizontal_Pod_Autoscaling___Kubernetes.jpg

HPA 会被 controller manager 启动,不断从 heapster 抓取所有 pod 的 metrics,计算出平均值,再控制 deployment 伸缩。我们的问题很明显出在计算平均值的那前半段。

HPA 启动和运行 #

Kubernetes 那么多代码,从哪看起呢? 我们先查看了 controller manager 的 log,发现了关键的几行

W0429 12:42:11.182073       5 horizontal.go:105] Failed to reconcile neo-staging-web: failed to compute desired number of replicas based on CPU utilization for Deployment/backend/neo-staging-web: failed to get CPU utilization: failed to get CPU consumption and request: metrics obtained for 0/2 of pods (sample missing pod: backend/neo-staging-web-v201-dqxj5)

这个 log 是在 k8s/controller/podautoscaler/horizontal.go:105 被打印的,逆着调用链,我们发现程序入口在 kube-controller-manager/controller-manager.go:53,接着在 cmd/kube-controller-manager/app/controllermanager.go:121 这个 Run 函数中启动了多个 controller,其中就包括 podautoscaler pkg 的 HorizontalController(cmd/kube-controller-manager/app/controllermanager.go:337)。当它被调用 .Run(wait.NeverStop) 的时候,就会创建一个 loop 每隔一段时间从 apiserver 获取 autoscaler 列表,再对每个 autoscaler 做处理。这个处理的过程(pkg/controller/podautoscaler/horizontal.go:258)包括获取相关监控数据、计算需要的 pod 数量和调用 apiserver 的 API 来更新 autoscaler 的 desired pod 数量。

获取监控数据的逻辑入口在这里 pkg/controller/podautoscaler/metrics/metrics_client.go:104。其中两个关键函数 GetCpuConsumptionAndRequestInMillis 和 getCpuUtilizationForPods 函数简化后是

func (h *HeapsterMetricsClient) GetCpuConsumptionAndRequestInMillis(...) (...) {
    podList, err := h.client.Core().Pods(namespace).
        List(api.ListOptions{LabelSelector: selector})

    // ... pods 必须是 running 并且有设置 requested CPU
    requestAvg := requestSum / int64(len(podNames))
    consumption, timestamp, err := h.getCpuUtilizationForPods(namespace, selector, podNames)
    return consumption, requestAvg, len(podNames), timestamp, nil
}

func (h *HeapsterMetricsClient) getCpuUtilizationForPods(namespace, selector, podNames) (int64, time.Time, error) {
    metricPath := fmt.Sprintf("/apis/metrics/v1alpha1/namespaces/%s/pods", namespace)
    params := map[string]string{"labelSelector": selector.String()}

    resultRaw, err := h.client.Core().Services(h.heapsterNamespace).
        ProxyGet(h.heapsterScheme, h.heapsterService, h.heapsterPort, metricPath, params).
        DoRaw()

    metrics := metrics_api.PodMetricsList{}
    err = json.Unmarshal(resultRaw, &metrics)

    if len(metrics.Items) != len(podNames) {
        missing := // 找出没有 metrics 的 pod
        hint := ""
        if len(missing) > 0 {
            hint = fmt.Sprintf(" (sample missing pod: %s/%s)", namespace, missing[0])
        }
        return 0, time.Time{}, fmt.Errorf("metrics obtained for %d/%d of pods%s", len(metrics.Items), len(podNames), hint)
    }
}

先通过 apiserver 得到 pod list,经过简单的判断和过滤,再调用 heapster 的 API 得到 metrics,只有返回的 metrics 和 pod 一致才会继续进行。从错误日志可以判断,问题就出在 heapster 返回的 metrics 少了。

heapster API 返回 pod metrics #

heapster 是一个单独的项目,在 k8s 中,heapster 通常以 pod 的形式被部署在 k8s 集群中,它从 k8s 的每个节点那里收集数据,经过处理之后再写到一些存储里。它也提供 API 来得到数据,比如刚刚看到的 /apis/metrics/v1alpha1/namespaces/:namespace/pods

由 build 的脚本或者直接搜索代码,很容易知道 heapster 是在 metrics/heapster.go:63 启动的,这里先初始化了 source(用来得到监控数据,比如 k8s)和 sink(用来保存数据,比如 influxdb),启动了用来收集和处理数据的 manager,最后启动了 HTTP server。先从上边的 API 调用入口看起 metrics/apis/metrics/handlers.go:188,这里获取了 pods 列表,然后从 MetricsSink 中取到相应的 metrics。MetricsSink 就是其中一种 sink,它比较简单,只是把长期(15m)和短期(140s)的数据放在 struct 里,metrics 的实际获取是异步进行的,这里先按下不表,先来看是哪里出的问题。从 log 中我们看到了如下的错误:

No metrics for pod backend/neo-staging-web-v201-dqxj5

但这块代码错误处理写得并不是很好,没有把更进一步的原因打到 log 里,所以我们很难知道是因为 MetricsSink 里没有数据,还是数据不正确。这里我们为了更快地定位问题,自己改了一下代码,在这个函数 metrics/apis/metrics/handlers.go:260 GetLatestDataBatch() 判空以及 parseResourceList error 判断的地方加了 log,把自己修改后的代码重新 build image 并运行。结论是因为 metrics 里没有 “cpu/usage_rate”(CPU usage on all cores in millicores)。因为是数据的问题,所以只看这段代码是不够的,我们需要知道 MetricsSink 的数据是如何被写入的。

heapster 从 Kubernetes 获取 metrics #

heapster 的 main 函数里先创建了 sourceManager、dataProcessors 和 sinkManager,再用它们创建了一个总的 manager(metrics/manager/manager.go:64),并运行它。这个运行的过程,其实就是创建了一个 goroutine,异步地不断进行数据从抓取到保存的整个过程。

简化后的代码如下:

// metrics/manager/manager.go:110
func (rm *realManager) housekeep(start, end time.Time) {
    select {
    go func(rm *realManager) {
        data := rm.source.ScrapeMetrics(start, end)

        for _, p := range rm.processors {
            newData, err := process(p, data)
            data = newData
        }
        rm.sink.ExportData(data)
    }(rm)
}

// metrics/sources/manager.go:78
func (this *sourceManager) ScrapeMetrics(start, end time.Time) *DataBatch {
    sources := this.metricsSourceProvider.GetMetricsSources()

    response := DataBatch{
        MetricSets: map[string]*MetricSet{},
    }
    for _, source := range sources {
        metrics := s.ScrapeMetrics(start, end)
        for key, value := range metrics.MetricSets {
            response.MetricSets[key] = value
        }
    }
    return &response
}

// metrics/processors/rate_calculator.go:32
func (this *RateCalculator) Process(batch *core.DataBatch) (*core.DataBatch, error) {
    if this.previousBatch == nil {
        this.previousBatch = batch
        return batch, nil
    }

    for key, newMs := range batch.MetricSets {
        if oldMs, found := this.previousBatch.MetricSets[key]; found {
            if !newMs.CreateTime.Equal(oldMs.CreateTime) {
                glog.V(4).Infof("Skipping rates for %s - different create time new:%v  old:%v", key, newMs.CreateTime, oldMs.CreateTime)
                // Create time for container must be the same.
                continue
            }

            for metricName, targetMetric := range this.rateMetricsMapping {
                // 通过新旧 metrics 来计算 rate,并修改 newMs
            }
        }
    }
    this.previousBatch = batch
    return batch, nil
}

这里会先得到所有的 sources,也就是每个 k8s cluster node 的 kubelet,然后调用 kubelet 的 “/stats/container/” 接口来得到 []cadvisor.ContainerInfo,它包含所有 container 的信息以及对应的 metrics。再用得到的数据来计算一些 rate metrics,比如前边提到过的 CpuUsageRate,也就是一段时间内的 CPU usage。但在计算之前做了一些判断,比如会比较前后两个 DataBatch 的 container 的创建时间。通过把 log 级别调到 4,我们发现这里会输出很多这样错误日志:

rate_calculator.go:51] Skipping rates for namespace:backend/pod:neo-staging-web-v201-ee4c3 - different create time new:2017-05-04 14:26:19.639205791 +0000 UTC  old:2017-05-04 14:25:19.591801877 +0000 UTC

所以基本可以确定,前边发现没有 CpuUsageRate 的原因是在这里跳过了计算。那为什么要比较 container 的创建时间呢?通过 git blame,我们在这个 issue https://github.com/kubernetes/heapster/issues/988 找到了答案,原来是为了处理 container 重启的情况。而实际上,container 并没有重启,但为什么 container 的创建时间会一直不一致呢?是从 kubelet 中获取的数据本身就有问题还是经过 heapster 的处理后造成的问题?

我们可以直接在 node 上边调用 kubelet 的 API 来看结果有什么问题,其中不太重要的信息被我略去了

$ curl -X "POST" -d '{"containerName":"/","subcontainers":true,"num_stats":1}' http://localhost:10255/stats/container
{
  "/system.slice/docker.service/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f": {
    "id": "cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "name": "/system.slice/docker.service/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "spec": {
      "creation_time": "2017-05-04T15:30:22.688799748Z",
      "labels": {
        "io.kubernetes.container.name": "neo-web",
        "io.kubernetes.pod.name": "neo-staging-web-v201-dqxj5",
        "io.kubernetes.pod.namespace": "backend"
      }
    }
  },
  "/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f": {
    "id": "cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "name": "/docker/cf372e95fb3ed22b8613576164867f273eca157c0d3c4112af196993b0b8125f",
    "spec": {
      "creation_time": "2017-05-04T15:30:43.173457599Z",
      "labels": {
        "io.kubernetes.container.name": "neo-web",
        "io.kubernetes.pod.name": "neo-staging-web-v201-dqxj5",
        "io.kubernetes.pod.namespace": "backend"
      }
    }
  }
}

MetricSet 的 key 是这三个 labels 拼起来的,container 的创建时间是 spec.creation_time。可以发现,我们有两份 container、pod 完全一样但 id 和创建时间却又细微差别的数据。所以我们基本可以确定 kubelet 返回的数据有问题。

 
10
Kudos
 
10
Kudos

Now read this

What’s SSD TRIM and why use it?

最近我们的一个 Mongo cluster 总是在周末的时候有大量的 IO 操作,并严重影响了 Mongo 的性能。然后发现问题出现的时候总是会执行一个 cron job – fstrim: $ cat /etc/crontab | grep weekly 47 6 * * 7 root test -x /usr/sbin/anacron || ( cd / && run-parts --report /etc/cron.weekly ) $ cat... Continue →