몇 년 전 쿠버네티스 이미 논의 공식 GitHub 블로그에서. 이후 서비스 배포를 위한 표준 기술이 되었습니다. Kubernetes는 이제 내부 및 공용 서비스의 상당 부분을 관리합니다. 클러스터가 성장하고 성능 요구 사항이 더욱 엄격해짐에 따라 Kubernetes의 일부 서비스에서 애플리케이션 자체의 로드로는 설명할 수 없는 지연 시간이 산발적으로 발생한다는 사실을 발견하기 시작했습니다.

기본적으로 애플리케이션은 최대 100ms 이상의 무작위 네트워크 대기 시간을 경험하므로 시간 초과 또는 재시도가 발생합니다. 서비스는 100ms보다 훨씬 빠르게 요청에 응답할 수 있을 것으로 예상되었습니다. 하지만 연결 자체에 너무 많은 시간이 걸리면 불가능합니다. 이와 별도로 우리는 밀리초가 소요되는 매우 빠른 MySQL 쿼리를 관찰했으며 MySQL은 밀리초 만에 완료되었지만 요청 애플리케이션의 관점에서는 응답에 100ms 이상이 걸렸습니다.

호출이 Kubernetes 외부에서 왔더라도 Kubernetes 노드에 연결할 때만 문제가 발생했다는 것이 즉시 분명해졌습니다. 문제를 재현하는 가장 쉬운 방법은 테스트입니다. 단조로운 생활을하다는 내부 호스트에서 실행되며 특정 포트에서 Kubernetes 서비스를 테스트하고 산발적으로 높은 대기 시간을 등록합니다. 이번 글에서는 이 문제의 원인을 어떻게 추적할 수 있었는지 살펴보겠습니다.

실패로 이어지는 체인의 불필요한 복잡성 제거

동일한 예를 재현함으로써 문제의 초점을 좁히고 불필요한 복잡성 계층을 제거하고 싶었습니다. 처음에는 Vegeta와 Kubernetes 포드 사이의 흐름에 요소가 너무 많았습니다. 더 깊은 네트워크 문제를 식별하려면 그 중 일부를 배제해야 합니다.

클라이언트(Vegeta)는 클러스터의 모든 노드와 TCP 연결을 생성합니다. Kubernetes는 다음을 사용하는 오버레이 네트워크(기존 데이터 센터 네트워크 위에)로 작동합니다. IPIP즉, 데이터 센터의 IP 패킷 내부에 오버레이 네트워크의 IP 패킷을 캡슐화합니다. 첫 번째 노드에 연결할 때 네트워크 주소 변환이 수행됩니다. 네트워크 주소 변환 (NAT) 상태 저장을 통해 Kubernetes 노드의 IP 주소 및 포트를 오버레이 네트워크(특히 애플리케이션이 있는 Pod)의 IP 주소 및 포트로 변환합니다. 들어오는 패킷의 경우 반대 순서의 작업이 수행됩니다. 서비스가 배포되고 이동됨에 따라 지속적으로 업데이트되고 변경되는 많은 상태와 많은 요소가 포함된 복잡한 시스템입니다.

공익 사업 tcpdump Vegeta 테스트에서는 TCP 핸드셰이크(SYN과 SYN-ACK 간) 중에 지연이 있습니다. 이러한 불필요한 복잡성을 제거하려면 다음을 사용할 수 있습니다. hping3 SYN 패킷을 사용한 간단한 "핑"용입니다. 응답 패킷에 지연이 있는지 확인한 후 연결을 재설정합니다. 100ms보다 큰 패킷만 포함하도록 데이터를 필터링하고 Vegeta의 전체 네트워크 계층 7 테스트보다 문제를 재현하는 더 쉬운 방법을 얻을 수 있습니다. 다음은 가장 느린 응답으로 필터링된 30927ms 간격으로 서비스 "노드 포트"(10)에서 TCP SYN/SYN-ACK를 사용하는 Kubernetes 노드 "ping"입니다.

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -S -p 30927 -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1485 win=29200 rtt=127.1 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1486 win=29200 rtt=117.0 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1487 win=29200 rtt=106.2 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=1488 win=29200 rtt=104.1 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5024 win=29200 rtt=109.2 ms

len=46 ip=172.16.47.27 ttl=59 DF id=0 sport=30927 flags=SA seq=5231 win=29200 rtt=109.2 ms

즉시 첫 번째 관찰을 할 수 있습니다. 시퀀스 번호와 타이밍으로 판단하면 이는 일회성 정체가 아님이 분명합니다. 지연은 종종 누적되어 결국 처리됩니다.

다음으로, 혼잡 발생에 어떤 구성 요소가 관련될 수 있는지 알아보고 싶습니다. 아마도 이것이 NAT에 있는 수백 개의 iptables 규칙 중 일부일까요? 아니면 네트워크의 IPIP 터널링에 문제가 있습니까? 이를 확인하는 한 가지 방법은 시스템의 각 단계를 제거하여 테스트하는 것입니다. NAT 및 방화벽 논리를 제거하고 IPIP 부분만 남겨두면 어떻게 되나요?

다행스럽게도 Linux에서는 시스템이 동일한 네트워크에 있는 경우 IP 오버레이 계층에 직접 쉽게 액세스할 수 있습니다.

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7346 win=0 rtt=127.3 ms

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7347 win=0 rtt=117.3 ms

len=40 ip=10.125.20.64 ttl=64 DF id=0 sport=0 flags=RA seq=7348 win=0 rtt=107.2 ms

결과를 보면 문제는 여전히 남아있습니다! iptables와 NAT는 제외됩니다. 그렇다면 문제는 TCP인가? 일반 ICMP 핑이 어떻게 진행되는지 살펴보겠습니다.

theojulienne@kube-node-client ~ $ sudo hping3 10.125.20.64 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=28 ip=10.125.20.64 ttl=64 id=42594 icmp_seq=104 rtt=110.0 ms

len=28 ip=10.125.20.64 ttl=64 id=49448 icmp_seq=4022 rtt=141.3 ms

len=28 ip=10.125.20.64 ttl=64 id=49449 icmp_seq=4023 rtt=131.3 ms

len=28 ip=10.125.20.64 ttl=64 id=49450 icmp_seq=4024 rtt=121.2 ms

len=28 ip=10.125.20.64 ttl=64 id=49451 icmp_seq=4025 rtt=111.2 ms

len=28 ip=10.125.20.64 ttl=64 id=49452 icmp_seq=4026 rtt=101.1 ms

len=28 ip=10.125.20.64 ttl=64 id=50023 icmp_seq=4343 rtt=126.8 ms

len=28 ip=10.125.20.64 ttl=64 id=50024 icmp_seq=4344 rtt=116.8 ms

len=28 ip=10.125.20.64 ttl=64 id=50025 icmp_seq=4345 rtt=106.8 ms

len=28 ip=10.125.20.64 ttl=64 id=59727 icmp_seq=9836 rtt=106.1 ms

결과는 문제가 사라지지 않았음을 보여줍니다. 아마도 이것은 IPIP 터널일까요? 테스트를 더욱 단순화해 보겠습니다.

이 두 호스트 간에 모든 패킷이 전송됩니까?

theojulienne@kube-node-client ~ $ sudo hping3 172.16.47.27 --icmp -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=61 id=41127 icmp_seq=12564 rtt=140.9 ms

len=46 ip=172.16.47.27 ttl=61 id=41128 icmp_seq=12565 rtt=130.9 ms

len=46 ip=172.16.47.27 ttl=61 id=41129 icmp_seq=12566 rtt=120.8 ms

len=46 ip=172.16.47.27 ttl=61 id=41130 icmp_seq=12567 rtt=110.8 ms

len=46 ip=172.16.47.27 ttl=61 id=41131 icmp_seq=12568 rtt=100.7 ms

len=46 ip=172.16.47.27 ttl=61 id=9062 icmp_seq=31443 rtt=134.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9063 icmp_seq=31444 rtt=124.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9064 icmp_seq=31445 rtt=114.2 ms

len=46 ip=172.16.47.27 ttl=61 id=9065 icmp_seq=31446 rtt=104.2 ms

두 개의 Kubernetes 노드가 서로 패킷, 심지어 ICMP ping을 보내는 상황을 단순화했습니다. 대상 호스트가 "불량"(일부는 다른 것보다 더 나쁨)인 경우에도 여전히 대기 시간이 표시됩니다.

이제 마지막 질문입니다. 왜 지연이 kube-node 서버에서만 발생합니까? 그리고 kube-node가 발신자일 때나 수신자일 때 이런 일이 발생하나요? 운 좋게도 이는 Kubernetes 외부의 호스트에서 동일한 "알려진 불량" 수신자를 사용하여 패킷을 보내면 쉽게 알아낼 수 있습니다. 보시다시피 문제는 사라지지 않았습니다.

theojulienne@shell ~ $ sudo hping3 172.16.47.27 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=312 win=0 rtt=108.5 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=5903 win=0 rtt=119.4 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=6227 win=0 rtt=139.9 ms

len=46 ip=172.16.47.27 ttl=61 DF id=0 sport=9876 flags=RA seq=7929 win=0 rtt=131.2 ms

그런 다음 이전 소스 kube-node에서 외부 호스트로 동일한 요청을 실행합니다(ping에 RX 및 TX 구성 요소가 모두 포함되므로 소스 호스트는 제외됨).

theojulienne@kube-node-client ~ $ sudo hping3 172.16.33.44 -p 9876 -S -i u10000 | egrep --line-buffered 'rtt=[0-9]{3}.'
^C
--- 172.16.33.44 hping statistic ---
22352 packets transmitted, 22350 packets received, 1% packet loss
round-trip min/avg/max = 0.2/7.6/1010.6 ms

대기 시간 패킷 캡처를 조사하여 몇 가지 추가 정보를 얻었습니다. 특히 발신자(하단)는 이 시간 초과를 볼 수 있지만 수신자(상단)는 이를 볼 수 없습니다. 델타 열(초)을 참조하십시오.

또한 수신자 측에서 TCP와 ICMP 패킷의 순서(시퀀스 번호 기준) 차이를 살펴보면 ICMP 패킷은 항상 전송된 순서와 동일하지만 타이밍이 다르게 도착합니다. 동시에 TCP 패킷이 때때로 인터리브되고 일부는 중단됩니다. 특히 SYN 패킷의 포트를 살펴보면 송신자 측에서는 순서가 있지만 수신자 측에서는 순서가 없습니다.

방법에는 미묘한 차이가 있습니다 네트워크 카드 데이터 센터와 같은 최신 서버는 TCP 또는 ICMP가 포함된 패킷을 처리합니다. 패킷이 도착하면 네트워크 어댑터는 "연결당 해시"합니다. 즉, 연결을 대기열로 나누고 각 대기열을 별도의 프로세서 코어로 보내려고 합니다. TCP의 경우 이 해시에는 소스 및 대상 IP 주소와 포트가 모두 포함됩니다. 즉, 각 연결은 (잠재적으로) 다르게 해시됩니다. ICMP의 경우 포트가 없으므로 IP 주소만 해시됩니다.

또 다른 새로운 관찰: 이 기간 동안 두 호스트 간의 모든 통신에서 ICMP가 지연되는 것을 볼 수 있지만 TCP는 그렇지 않습니다. 이는 원인이 RX 대기열 해싱과 관련이 있을 가능성이 높다는 것을 알려줍니다. 정체는 거의 확실하게 응답 전송이 아니라 RX 패킷 처리에 있습니다.

이렇게 하면 가능한 원인 목록에서 패킷 전송이 제거됩니다. 이제 우리는 일부 kube-node 서버의 수신 측에서 패킷 처리 문제가 발생한다는 것을 알고 있습니다.

Linux 커널의 패킷 처리 이해

일부 kube-node 서버의 수신자에서 문제가 발생하는 이유를 이해하기 위해 Linux 커널이 패킷을 처리하는 방법을 살펴보겠습니다.

가장 단순한 기존 구현으로 돌아가서 네트워크 카드는 패킷을 수신하고 전송합니다. 방해하다 처리해야 할 패키지가 있다는 Linux 커널. 커널은 다른 작업을 중지하고 컨텍스트를 인터럽트 처리기로 전환하고 패킷을 처리한 다음 현재 작업으로 돌아갑니다.

이러한 컨텍스트 전환은 느립니다. 10년대에는 90Mbps 네트워크 카드에서는 대기 시간이 눈에 띄지 않았을 수도 있지만 초당 최대 처리량이 10만 패킷인 최신 15G 카드에서는 소형 XNUMX코어 서버의 각 코어가 수백만 번 중단될 수 있습니다. 초당 횟수.

지속적으로 인터럽트를 처리하지 않기 위해 몇 년 전에 Linux에 추가되었습니다. 나피: 모든 최신 드라이버가 고속에서 성능을 향상시키기 위해 사용하는 네트워크 API입니다. 낮은 속도에서도 커널은 여전히 ​​예전 방식으로 네트워크 카드로부터 인터럽트를 받습니다. 임계값을 초과하는 충분한 패킷이 도착하면 커널은 인터럽트를 비활성화하고 대신 네트워크 어댑터를 폴링하고 패킷을 청크 단위로 수집하기 시작합니다. 처리는 Softirq에서 수행됩니다. 소프트웨어 인터럽트의 컨텍스트 시스템 호출 및 하드웨어 중단 후 커널(사용자 공간과 반대)이 이미 실행 중일 때.

이는 훨씬 빠르지만 다른 문제를 야기합니다. 패킷이 너무 많으면 네트워크 카드에서 패킷을 처리하는 데 모든 시간이 소요되고 사용자 공간 프로세스에는 실제로 이러한 대기열을 비울 시간이 없습니다(TCP 연결에서 읽기 등). 결국 대기열이 채워지고 패킷 삭제가 시작됩니다. 균형을 찾기 위해 커널은 Softirq 컨텍스트에서 처리되는 최대 패킷 수에 대한 예산을 설정합니다. 이 예산이 초과되면 별도의 스레드가 활성화됩니다. ksoftirqd (그 중 하나를 볼 수 있습니다. ps 코어당) 일반적인 syscall/인터럽트 경로 외부에서 이러한 Softirq를 처리합니다. 이 스레드는 리소스를 공정하게 할당하려고 시도하는 표준 프로세스 스케줄러를 사용하여 예약됩니다.

커널이 패킷을 처리하는 방법을 연구한 결과 혼잡이 발생할 가능성이 있음을 알 수 있습니다. Softirq 호출의 수신 빈도가 낮아지면 패킷은 네트워크 카드의 RX 대기열에서 처리될 때까지 기다려야 합니다. 이는 일부 작업이 프로세서 코어를 차단하거나 다른 요인으로 인해 코어가 Softirq를 실행하지 못하기 때문일 수 있습니다.

처리 범위를 핵심 또는 방법으로 좁히기

Softirq 지연은 현재로서는 추측일 뿐입니다. 하지만 그것은 말이 되고, 우리는 매우 유사한 것을 보고 있다는 것을 알고 있습니다. 따라서 다음 단계는 이 이론을 확인하는 것입니다. 확인된 경우 지연 이유를 찾으십시오.

느린 패킷으로 돌아가 보겠습니다.

len=46 ip=172.16.53.32 ttl=61 id=29573 icmp_seq=1953 rtt=99.3 ms

len=46 ip=172.16.53.32 ttl=61 id=29574 icmp_seq=1954 rtt=89.3 ms

len=46 ip=172.16.53.32 ttl=61 id=29575 icmp_seq=1955 rtt=79.2 ms

len=46 ip=172.16.53.32 ttl=61 id=29576 icmp_seq=1956 rtt=69.1 ms

len=46 ip=172.16.53.32 ttl=61 id=29577 icmp_seq=1957 rtt=59.1 ms

len=46 ip=172.16.53.32 ttl=61 id=29790 icmp_seq=2070 rtt=75.7 ms

len=46 ip=172.16.53.32 ttl=61 id=29791 icmp_seq=2071 rtt=65.6 ms

len=46 ip=172.16.53.32 ttl=61 id=29792 icmp_seq=2072 rtt=55.5 ms

앞에서 설명한 것처럼 이러한 ICMP 패킷은 단일 RX NIC 대기열로 해시되고 단일 CPU 코어에서 처리됩니다. Linux 작동 방식을 이해하려면 프로세스를 추적하기 위해 이러한 패키지가 어디에서(어떤 CPU 코어에서) 어떻게(softirq, ksoftirqd) 처리되는지 아는 것이 유용합니다.

이제 실시간으로 Linux 커널을 모니터링할 수 있는 도구를 사용할 차례입니다. 여기서 우리는 숨은 참조. 이 도구 세트를 사용하면 커널에서 임의의 함수를 연결하고 이벤트를 처리하고 결과를 반환할 수 있는 사용자 공간 Python 프로그램에 버퍼링하는 작은 C 프로그램을 작성할 수 있습니다. 커널에 임의의 기능을 연결하는 것은 복잡한 문제이지만 이 유틸리티는 보안을 극대화하도록 설계되었으며 테스트 또는 개발 환경에서 쉽게 재현되지 않는 생산 문제의 종류를 정확히 추적하도록 설계되었습니다.

여기서의 계획은 간단합니다. 커널이 이러한 ICMP 핑을 처리한다는 것을 알고 있으므로 커널 기능에 후크를 겁니다. icmp_echo, 들어오는 ICMP 에코 요청 패킷을 수락하고 ICMP 에코 응답 보내기를 시작합니다. icmp_seq 번호를 증가시켜 패킷을 식별할 수 있습니다. hping3 위.

암호 숨은 참조 스크립트 복잡해 보이지만 생각만큼 무섭지는 않습니다. 기능 icmp_echo 전송하다 struct sk_buff *skb: "에코 요청"이 포함된 패킷입니다. 우리는 그것을 추적하고 시퀀스를 뽑아낼 수 있어요 echo.sequence (이것은 icmp_seq 작성자: hping3 выше), 이를 사용자 공간으로 보냅니다. 현재 프로세스 이름/ID를 캡처하는 것도 편리합니다. 다음은 커널이 패킷을 처리하는 동안 직접 볼 수 있는 결과입니다.

TGID PID 프로세스 이름 ICMP_SEQ 0 0 swapper/11 770 0 0 swapper/11 771 0 0 swapper/11 772 0 0 swapper/11 773 0 0 swapper/11 774 20041 20086 prometheus 775 0 0 swapper/11 776 0 0 swapper/11 777 0 0 11 스왑퍼/778 4512 4542 779 스포크-보고서-s XNUMX

여기서 주목해야 할 점은 문맥상 softirq 시스템 호출을 수행한 프로세스는 실제로 커널 컨텍스트에서 패킷을 안전하게 처리하는 커널인 경우 "프로세스"로 표시됩니다.

이 도구를 사용하면 특정 프로세스를 지연을 나타내는 특정 패키지와 연결할 수 있습니다. hping3. 간단하게 만들어보자 grep 특정 값에 대한 이 캡처에 대해 icmp_seq. 위의 icmp_seq 값과 일치하는 패킷은 위에서 관찰한 RTT와 함께 기록되었습니다(괄호 안은 50ms 미만의 RTT 값으로 인해 필터링한 패킷에 대한 예상 RTT 값입니다).

TGID PID 프로세스 이름 ICMP_SEQ ** RTT -- 10137 10436 cadvisor 1951 10137 10436 cadvisor 1952 76 76 ksoftirqd/11 1953 ** 99ms 76 76 ksoftirqd/11 1954 ** 89ms 76 76 ksoftir qd/11 1955 79 ** 76ms 76 11 ksoftirqd/ 1956 69 ** 76ms 76 11 ksoftirqd/1957 59 ** 76ms 76 11 ksoftirqd/1958 49 ** (76ms) 76 11 ksoftirqd/1959 39 ** (76ms) 76 11 ksoftirqd/1960 29 ** (76ms) 76 11 ksoft irqd/ 1961 19 ** (76ms) 76 11 ksoftirqd/1962 9 ** (10137ms) -- 10436 2068 cadvisor 10137 10436 2069 cadvisor 76 76 11 ksoftirqd/2070 75 ** 76ms 76 11 ksoftirqd/2071 65 76 ** 76ms 11 2072 ksoftirqd/55 76 ** 76ms 11 2073 ksoftirqd/45 76 ** (76ms) 11 2074 ksoftirqd/35 76 ** (76ms) 11 2075 ksoftirqd/25 76 ** (76ms) 11 2076 ksoftirqd/15 76 ** (76ms) ) 11 2077 ksoftirqd/5 XNUMX ** (XNUMXms)

결과는 우리에게 몇 가지 사실을 알려줍니다. 첫째, 이러한 모든 패키지는 컨텍스트에 의해 처리됩니다. ksoftirqd/11. 이는 이 특정 컴퓨터 쌍의 경우 ICMP 패킷이 수신 측의 코어 11로 해시되었음을 의미합니다. 또한 잼이 발생할 때마다 시스템 호출의 맥락에서 처리되는 패킷이 있다는 것을 알 수 있습니다. cadvisor. 그런 다음 ksoftirqd 작업을 인계받아 누적된 대기열을 처리합니다. 정확히 그 이후에 누적된 패킷 수입니다. cadvisor.

직전에 항상 작동한다는 사실 cadvisor, 문제에 그가 관여했음을 의미합니다. 아이러니하게도 그 목적은 캐드바이저 - 이러한 성능 문제를 일으키기보다는 "실행 중인 컨테이너의 리소스 사용량 및 성능 특성을 분석"합니다.

컨테이너의 다른 측면과 마찬가지로 이들은 모두 고도로 발전된 도구이므로 예상치 못한 상황에서 성능 문제가 발생할 수 있습니다.

패킷 대기열 속도를 늦추기 위해 cadvisor는 무엇을 합니까?

이제 우리는 충돌이 어떻게 발생하는지, 어떤 프로세스가 충돌을 일으키는지, 어떤 CPU에서 충돌이 발생하는지 꽤 잘 이해했습니다. 하드 블로킹으로 인해 Linux 커널이 예약할 시간이 없다는 것을 알 수 있습니다. ksoftirqd. 그리고 패킷이 컨텍스트에 따라 처리되는 것을 볼 수 있습니다. cadvisor. 다음과 같이 가정하는 것이 논리적이다. cadvisor 느린 syscall을 실행한 후 해당 시간에 누적된 모든 패킷이 처리됩니다.

이것은 이론이지만 어떻게 테스트합니까? 우리가 할 수 있는 일은 이 프로세스 전반에 걸쳐 CPU 코어를 추적하고, 패킷 수가 예산을 초과하고 ksoftirqd가 호출되는 지점을 찾은 다음 조금 더 되돌아가 그 지점 직전에 CPU 코어에서 정확히 무엇이 실행되고 있었는지 확인하는 것입니다. . 이는 몇 밀리초마다 CPU를 엑스레이로 촬영하는 것과 같습니다. 다음과 같이 보일 것입니다:

편리하게도 이 모든 작업은 기존 도구를 사용하여 수행할 수 있습니다. 예를 들어, 성능 기록 지정된 빈도로 지정된 CPU 코어를 확인하고 사용자 공간과 Linux 커널을 모두 포함하여 실행 중인 시스템에 대한 호출 일정을 생성할 수 있습니다. 이 기록을 가져와 프로그램의 작은 포크를 사용하여 처리할 수 있습니다. 플레임그래프 스택 추적의 순서를 유지하는 Brendan Gregg의 글입니다. 1ms마다 한 줄 스택 추적을 저장한 다음 추적이 발생하기 100밀리초 전에 샘플을 강조 표시하고 저장할 수 있습니다. ksoftirqd:

# record 999 times a second, or every 1ms with some offset so not to align exactly with timers
sudo perf record -C 11 -g -F 999
# take that recording and make a simpler stack trace.
sudo perf script 2>/dev/null | ./FlameGraph/stackcollapse-perf-ordered.pl | grep ksoftir -B 100

결과는 다음과 같습니다.

(сотни следов, которые выглядят похожими)

cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_iter cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages cadvisor;[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];[cadvisor];entry_SYSCALL_64_after_swapgs;do_syscall_64;sys_read;vfs_read;seq_read;memcg_stat_show;mem_cgroup_nr_lru_pages;mem_cgroup_node_nr_lru_pages ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;ixgbe_poll;ixgbe_clean_rx_irq;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;bond_handle_frame;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;ipip_tunnel_xmit;ip_tunnel_xmit;iptunnel_xmit;ip_local_out;dst_output;__ip_local_out;nf_hook_slow;nf_iterate;nf_conntrack_in;generic_packet;ipt_do_table;set_match_v4;ip_set_test;hash_net4_kadt;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;hash_net4_test ksoftirqd/11;ret_from_fork;kthread;kthread;smpboot_thread_fn;smpboot_thread_fn;run_ksoftirqd;__do_softirq;net_rx_action;gro_cell_poll;napi_gro_receive;netif_receive_skb_internal;inet_gro_receive;__netif_receive_skb_core;ip_rcv_finish;ip_rcv;ip_forward_finish;ip_forward;ip_finish_output;nf_iterate;ip_output;ip_finish_output2;__dev_queue_xmit;dev_hard_start_xmit;dev_queue_xmit_nit;packet_rcv;tpacket_rcv;sch_direct_xmit;validate_xmit_skb_list;validate_xmit_skb;netif_skb_features;ixgbe_xmit_frame_ring;swiotlb_dma_mapping_error;__dev_queue_xmit;dev_hard_start_xmit;__bpf_prog_run;__bpf_prog_run

여기에는 많은 것들이 있지만 가장 중요한 것은 앞서 ICMP 추적 프로그램에서 본 "ksoftirqd 이전의 cadvisor" 패턴을 발견했다는 것입니다. 무슨 뜻이에요?

각 라인은 특정 시점의 CPU 추적입니다. 한 줄의 스택 아래로 호출되는 각 호출은 세미콜론으로 구분됩니다. 줄 중간에 syscall이 호출되는 것을 볼 수 있습니다. read(): .... ;do_syscall_64;sys_read; .... 그래서 Cadvisor는 시스템 호출에 많은 시간을 소비합니다. read()기능과 관련된 mem_cgroup_* (호출 스택의 맨 위/줄 끝).

호출 추적에서 정확히 무엇을 읽고 있는지 확인하는 것은 불편하므로 다음을 실행해 보겠습니다. strace cadvisor가 수행하는 작업을 살펴보고 100ms보다 긴 시스템 호출을 찾아보겠습니다.

theojulienne@kube-node-bad ~ $ sudo strace -p 10137 -T -ff 2>&1 | egrep '<0.[1-9]'
[pid 10436] <... futex resumed> ) = 0 <0.156784>
[pid 10432] <... futex resumed> ) = 0 <0.258285>
[pid 10137] <... futex resumed> ) = 0 <0.678382>
[pid 10384] <... futex resumed> ) = 0 <0.762328>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 658 <0.179438>
[pid 10384] <... futex resumed> ) = 0 <0.104614>
[pid 10436] <... futex resumed> ) = 0 <0.175936>
[pid 10436] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.228091>
[pid 10427] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 577 <0.207334>
[pid 10411] <... epoll_ctl resumed> ) = 0 <0.118113>
[pid 10382] <... pselect6 resumed> ) = 0 (Timeout) <0.117717>
[pid 10436] <... read resumed> "cache 154234880nrss 507904nrss_h"..., 4096) = 660 <0.159891>
[pid 10417] <... futex resumed> ) = 0 <0.917495>
[pid 10436] <... futex resumed> ) = 0 <0.208172>
[pid 10417] <... futex resumed> ) = 0 <0.190763>
[pid 10417] <... read resumed> "cache 0nrss 0nrss_huge 0nmapped_"..., 4096) = 576 <0.154442>

예상한 대로 여기서는 느린 호출이 표시됩니다. read(). 읽기 작업 및 컨텍스트 내용에서 mem_cgroup 이러한 도전은 분명하다 read() 파일을 참조하세요 memory.stat, 메모리 사용량 및 cgroup 제한(Docker의 리소스 격리 기술)을 보여줍니다. cadvisor 도구는 이 파일을 쿼리하여 컨테이너에 대한 리소스 사용량 정보를 얻습니다. 커널이나 캐드바이저가 예상치 못한 일을 하고 있는지 확인해 보겠습니다.

theojulienne@kube-node-bad ~ $ time cat /sys/fs/cgroup/memory/memory.stat >/dev/null

real 0m0.153s
user 0m0.000s
sys 0m0.152s
theojulienne@kube-node-bad ~ $

이제 우리는 버그를 재현하고 Linux 커널이 병리 현상에 직면하고 있음을 이해할 수 있습니다.

읽기 작업이 왜 그렇게 느린가요?

이 단계에서는 유사한 문제에 대한 다른 사용자의 메시지를 찾는 것이 훨씬 쉽습니다. 결과적으로, Cadvisor 추적기에서 이 버그는 다음과 같이 보고되었습니다. 과도한 CPU 사용 문제, 대기 시간이 네트워크 스택에 무작위로 반영된다는 사실을 아무도 알아차리지 못했을 뿐입니다. 실제로 cadvisor가 예상보다 더 많은 CPU 시간을 소비하고 있다는 사실이 확인되었지만 이는 그다지 중요하지 않았습니다. 우리 서버에는 많은 CPU 리소스가 있어서 문제를 주의 깊게 조사하지 않았기 때문입니다.

문제는 cgroup이 네임스페이스(컨테이너) 내의 메모리 사용량을 고려한다는 것입니다. 이 cgroup의 모든 프로세스가 종료되면 Docker는 메모리 cgroup을 해제합니다. 그러나 "메모리"는 단순한 프로세스 메모리가 아닙니다. 프로세스 메모리 자체는 더 이상 사용되지 않지만 커널은 메모리 cgroup에 캐시된 dentries 및 inode(디렉터리 및 파일 메타데이터)와 같은 캐시된 콘텐츠를 여전히 할당하는 것으로 보입니다. 문제 설명에서:

좀비 cgroups: 프로세스가 없고 삭제되었지만 여전히 메모리가 할당된 cgroup입니다(제 경우에는 dentry 캐시에서, 페이지 캐시나 tmpfs에서 할당할 수도 있음).

cgroup을 해제할 때 캐시에 있는 모든 페이지에 대한 커널의 확인은 매우 느릴 수 있으므로 지연 프로세스가 선택됩니다. 이러한 페이지가 다시 요청될 때까지 기다린 다음 메모리가 실제로 필요할 때 마지막으로 cgroup을 지웁니다. 이 시점까지는 통계를 수집할 때 cgroup이 계속 고려됩니다.

성능 관점에서 보면 성능을 위해 메모리를 희생했습니다. 캐시된 메모리를 일부 남겨두어 초기 정리 속도를 높였습니다. 이건 괜찮아. 커널이 캐시된 메모리 중 마지막 메모리를 사용하면 결국 cgroup이 지워지므로 이를 "누출"이라고 부를 수 없습니다. 불행하게도 검색 메커니즘의 구체적인 구현은 memory.stat 이 커널 버전(4.9)에서는 우리 서버의 엄청난 양의 메모리와 결합되어 최신 캐시 데이터를 복원하고 cgroup 좀비를 지우는 데 훨씬 더 오랜 시간이 걸린다는 것을 의미합니다.

우리 노드 중 일부에는 cgroup 좀비가 너무 많아서 읽기 및 대기 시간이 XNUMX초를 초과한 것으로 나타났습니다.

Cadvisor 문제에 대한 해결 방법은 시스템 전체에서 dentries/inodes 캐시를 즉시 해제하는 것입니다. 이렇게 하면 호스트의 읽기 대기 시간과 네트워크 대기 시간이 즉시 제거됩니다. 캐시를 지우면 캐시된 좀비 cgroup 페이지도 켜지고 해제되기 때문입니다. 이는 해결책은 아니지만 문제의 원인을 확인합니다.

최신 커널 버전(4.19+)에서는 호출 성능이 향상된 것으로 나타났습니다. memory.stat이므로 이 커널로 전환하면 문제가 해결되었습니다. 동시에 우리는 Kubernetes 클러스터에서 문제가 있는 노드를 감지하고, 적절하게 드레이닝하고 재부팅하는 도구를 보유했습니다. 우리는 모든 클러스터를 조사하여 대기 시간이 충분히 높은 노드를 찾아 재부팅했습니다. 이로써 나머지 서버의 OS를 업데이트할 시간이 생겼습니다.

최대 합계

이 버그로 인해 수백 밀리초 동안 RX NIC 대기열 처리가 중단되었기 때문에 짧은 연결에서 높은 대기 시간과 MySQL 요청 및 응답 패킷 사이와 같은 중간 연결 대기 시간이 동시에 발생했습니다.

Kubernetes와 같은 가장 기본적인 시스템의 성능을 이해하고 유지하는 것은 이를 기반으로 하는 모든 서비스의 안정성과 속도에 매우 중요합니다. 실행하는 모든 시스템은 Kubernetes 성능 향상의 이점을 누릴 수 있습니다.

출처 : habr.com