Investigating a Kubernetes Machine Kernel Problem

This investigation happened in November 2020. I never had time to write a blog describing the course of events; now’s a good chance to write it all up.

The Specific Phenomenon

An application in the production environment had slow interface problems!!

From this phenomenon alone, countless causes could be listed. This blog mainly narrates the several investigations and how the cause was finally determined. It may not apply to other clusters — take it as a reference. The investigation was fairly lengthy; too much time has passed and I can’t possibly recall every detail — please forgive me.

Network Topology

When network requests flow into the cluster, for our cluster’s structure:

user request => Nginx => Ingress => uwsgi

Don’t ask why there’s Nginx as well as Ingress. Historical reasons — some work temporarily needs to be borne by Nginx.

First Localization

When requests slow down, the immediate thought is: did the program slow down? So after discovering the problem, I first added a simple small interface in uwsgi — an interface that processes fast and returns data immediately — then requested it periodically. After running several days, I confirmed this interface’s access speed was also slow, ruling out program problems and preparing to search the chain for the cause.

Second Localization – Simple Full-Chain Data Statistics (TL;DR)

Since our Nginx has 2 layers, each needed separate confirmation to see which layer was slow. The request volume is fairly large; checking every request would be inefficient and might mask the real cause, so this process used statistics — viewing the two Nginx layers’ logs separately. Since logs were already connected to elk, the elk data-filtering script is roughly:

{
  "bool": {
    "must": [
      {
        "match_all": {}
      },
      {
        "match_phrase": {
          "app_name": {
            "query": "xxxx"
          }
        }
      },
      {
        "match_phrase": {
          "path": {
            "query": "/app/v1/user/ping"
          }
        }
      },
      {
        "range": {
          "request_time": {
            "gte": 1,
            "lt": 10
          }
        }
      },
      {
        "range": {
          "@timestamp": {
            "gt": "2020-11-09 00:00:00",
            "lte": "2020-11-12 00:00:00",
            "format": "yyyy-MM-dd HH:mm:ss",
            "time_zone": "+08:00"
          }
        }
      }
    ]
  }
}

Data Processing Scheme

Based on trace_id, the Nginx logs and Ingress logs can be obtained via elk’s api.

# this data structure records statistics results;
# [[0, 0.1], 3] means 3 records fell in the 0~0.1 interval
# because decimal and interval comparisons are troublesome, integers are used — the 0~35 here is actually the 0~3.5s interval
# ingress_cal_map = [
#     [[0, 0.1], 0],
#     [[0.1, 0.2], 0],
#     [[0.2, 0.3], 0],
#     [[0.3, 0.4], 0],
#     [[0.4, 0.5], 0],
#     [[0.5, 1], 0],
# ]
ingress_cal_map = []
for x in range(0, 35, 1):
    ingress_cal_map.append(
        [[x, (x+1)], 0]
    )
nginx_cal_map = copy.deepcopy(ingress_cal_map)
nginx_ingress_gap = copy.deepcopy(ingress_cal_map)
ingress_upstream_gap = copy.deepcopy(ingress_cal_map)


def trace_statisics():
    trace_ids = []
    # the trace_ids here were pre-queried — those of requests with longer response times
    with open(trace_id_file) as f:
        data = f.readlines()
        for d in data:
            trace_ids.append(d.strip())

    cnt = 0
    for trace_id in trace_ids:
        try:
            access_data, ingress_data = get_igor_trace(trace_id)
        except TypeError as e:
            # try once more
            try:
                access_data, ingress_data = get_igor_trace.force_refresh(trace_id)
            except TypeError as e:
                print("Can't process trace {}: {}".format(trace_id, e))
                continue
        if access_data['path'] != "/app/v1/user/ping":  # filter dirty data
            continue
        if 'request_time' not in ingress_data:
            continue

        def get_int_num(data):  # uniformly *10 the data
            return int(float(data) * 10)

        # statistics for each interval segment — maybe a bit verbose and repetitive, but sufficient for my statistics at the time
        ingress_req_time = get_int_num(ingress_data['request_time'])
        ingress_upstream_time = get_int_num(ingress_data['upstream_response_time'])
        for cal in ingress_cal_map:
            if ingress_req_time >= cal[0][0] and ingress_req_time < cal[0][1]:
                cal[1] += 1
                break

        nginx_req_time = get_int_num(access_data['request_time'])
        for cal in nginx_cal_map:
            if nginx_req_time >= cal[0][0] and nginx_req_time < cal[0][1]:
                cal[1] += 1
                break

        gap = nginx_req_time - ingress_req_time
        for cal in nginx_ingress_gap:
            if gap >= cal[0][0] and gap <= cal[0][1]:
                cal[1] += 1
                break

        gap = ingress_req_time - ingress_upstream_time
        for cal in ingress_upstream_gap:
            if gap >= cal[0][0] and gap <= cal[0][1]:
                cal[1] += 1
                break

I made statistics for request_time(nginx), request_time(ingress), and requet_time(nginx) - request_time(ingress) respectively.

The final statistics were roughly:

Result Analysis

We had about 3000 records in total!

Chart 1: Over half the requests fell in the 11.1s interval; 1s2s requests were fairly even, then fewer and fewer.

Chart 2: About 1/4 of requests had actually returned within 0.1s, but 1/4 also landed in 1~1.1s; subsequent results resemble chart 1.

Combining charts 1 and 2: some requests’ processing time on the Ingress side was actually fairly short.

Chart 3: Fairly obvious — 2/3 of requests stay consistent in response time; 1/3 have about 1s of delay.

Summary

From the statistics: both Nginx => Ingress and Ingress => upstream had varying degrees of delay. For applications exceeding 1s, about 2/3 of the delay came from Ingress=>upstream and 1/3 from Nginx=>Ingress.

Deeper Investigation - Packet Capture Handling (TL;DR)

Packet capture investigation mainly targeted Ingress=>uwsgi. Since packet delays were only sporadic, all packets had to be captured then filtered… This is a record with a long request time; this interface itself should return quickly.

{
  "_source": {
    "INDEX": "51",
    "path": "/app/v1/media/",
    "referer": "",
    "user_agent": "okhttp/4.8.1",
    "upstream_connect_time": "1.288",
    "upstream_response_time": "1.400",
    "TIMESTAMP": "1605776490465",
    "request": "POST /app/v1/media/ HTTP/1.0",
    "status": "200",
    "proxy_upstream_name": "default-prod-XXX-80",
    "response_size": "68",
    "client_ip": "XXXXX",
    "upstream_addr": "172.32.18.194:6000",
    "request_size": "1661",
    "@source": "XXXX",
    "domain": "XXX",
    "upstream_status": "200",
    "@version": "1",
    "request_time": "1.403",
    "protocol": "HTTP/1.0",
    "tags": ["_dateparsefailure"],
    "@timestamp": "2020-11-19T09:01:29.000Z",
    "request_method": "POST",
    "trace_id": "87bad3cf9d184df0:87bad3cf9d184df0:0:1"
  }
}

Ingress-side packets

uwsgi-side packets

Packet Flow

Recall the TCP three-way handshake:

• First from the Ingress side: the connection started at 21.585446; at 22.588023 a packet retransmission occurred.

• From the Node side: the node received the syn shortly after the ingress packet was sent and immediately returned the syn — but somehow it only appeared at the ingress 1s later.

One point is rather concerning: even though packet retransmission occurred, there was no packet loss. From the two machines’ packet flow, in this request most of the time was caused by packets arriving late — retransmission was only the surface phenomenon; the real problem was packet delay.

Not Only ack Packets Were Delayed

From random packet captures, not only SYN ACK was retransmitted:

Some FIN ACK were too — packet delay is probabilistic behavior!!!

Summary

Looking at this capture alone might only confirm packet loss occurred. But combined with Ingress and Nginx request logs: if packet loss happens during the tcp connection phase, then in the Ingress we can view upstream_connect_time to roughly estimate the timeout situation. This was how I organized the records at the time:

I initially guessed this time was mainly consumed during TCP connection establishment, because connection establishment exists in both Nginx forwards, and our chain uses short connections entirely. Next I planned to add the $upstream_connect_time variable to record connection establishment time. http://nginx.org/en/docs/http/ngx_http_upstream_module.html

Follow-up Work

Since we could learn that tcp connection establishment took a long time, we could use it as a measurement metric. I also modified wrk, adding connection time measurement; the concrete PR is here (https://github.com/wg/wrk/pull/447). We can use this metric to gauge backend service conditions.

Seeking Experts — Whether They Met Similar Problems

I did the above work several times back and forth with no clues, so I consulted other K8S experts in the company. One expert provided an idea:

If host machine latency is also high, temporarily rule out the host-to-container path. We previously investigated a latency problem: it was caused by k8s monitoring tools periodically cat-ing cgroup statistics under proc, but due to docker’s frequent destruction/recreation and the kernel cache mechanism, each cat took very long, occupying the kernel and causing network latency. Could you check whether your hosts have a similar situation? It’s not necessarily cgroup — any operation frequently trapping into the kernel could cause high latency

This looks just like the cgroup we investigated: hosts have some periodic tasks; as executions accumulate, they occupy more and more kernel resources, and past a certain level they affect network latency

The experts also provided a kernel checking tool (can track and locate interrupt or soft-interrupt disable times):

https://github.com/bytedance/trace-irqoff

The problematic ingress machines had especially many latency entries — many errors like this, which other machines didn’t have:

Then I traced the kubelet on the machines once; from the flame graph it was confirmed that massive time was spent reading kernel information.

The concrete code is as follows:

Summary

Following the direction the expert gave, the real cause could basically be determined: too many scheduled task executions on the machine, kernel cache kept growing, slowing the kernel. Once it slowed, tcp handshake times lengthened, finally degrading user experience. Having found the problem, the solution was easy to search up: add tasks checking whether the kernel has slowed; if slow, clean it once:

sync && echo 3 > /proc/sys/vm/drop_caches

Summary

This investigation began with an application-layer problem affecting user experience, then extended to the network layer, going through a long packet-capture process. I also added my own scripts for metric measurement, then located the concrete application via kernel tools, and finally located a more precise anomaly position via the flame graph made with the application’s pprof tool. During this I couldn’t handle the problem alone, so I asked other experts for help; the experts are well-informed and could offer possible conjectures — very helpful indeed.

When you find a machine slow at everything, yet cpu and kernel aren’t the bottleneck, it’s possible the kernel has slowed.

I hope this article helps everyone investigating cluster problems in the future.