eBPF/BCC를 사용하여 높은 Ceph 대기 시간부터 커널 패치까지

Linux에는 커널과 애플리케이션을 디버깅하기 위한 수많은 도구가 있습니다. 대부분은 애플리케이션 성능에 부정적인 영향을 미치며 프로덕션에 사용할 수 없습니다.

몇 년 전에는 또 다른 도구가 개발되었습니다 - eBPF. 이를 통해 낮은 오버헤드로 프로그램을 다시 빌드하거나 타사 모듈을 커널에 로드할 필요 없이 커널 및 사용자 응용 프로그램을 추적할 수 있습니다.

eBPF를 사용하는 애플리케이션 유틸리티는 이미 많이 있으며, 이 기사에서는 라이브러리를 기반으로 자신만의 프로파일링 유틸리티를 작성하는 방법을 살펴보겠습니다. PythonBCC. 이 기사는 실제 사건을 바탕으로 작성되었습니다. 특정 상황에서 기존 유틸리티를 어떻게 사용할 수 있는지 보여주기 위해 문제를 해결하는 방법을 살펴보겠습니다.

세프는 느리다

Ceph 클러스터에 새 호스트가 추가되었습니다. 일부 데이터를 서버로 마이그레이션한 후 쓰기 요청 처리 속도가 다른 서버보다 훨씬 낮다는 것을 확인했습니다.

다른 플랫폼과 달리 이 호스트는 bcache와 새로운 Linux 4.15 커널을 사용했습니다. 이 구성의 호스트가 여기에서 사용된 것은 이번이 처음입니다. 그리고 그 순간 문제의 근본 원인은 이론적으로 무엇이든 될 수 있다는 것이 분명해졌습니다.

호스트 조사

먼저 ceph-osd 프로세스 내부에서 어떤 일이 일어나는지 살펴보겠습니다. 이를 위해 우리는 반환 한 и 화염경 (자세한 내용은 읽을 수 있습니다. 여기에):

그림은 우리에게 기능을 알려줍니다 fdatasync() 함수에 요청을 보내는 데 많은 시간을 소비했습니다. generic_make_request(). 이는 문제의 원인이 osd 데몬 자체 외부에 있을 가능성이 높다는 것을 의미합니다. 이는 커널일 수도 있고 디스크일 수도 있습니다. iostat 출력에서는 bcache 디스크의 요청 처리 시 높은 대기 시간이 나타났습니다.

호스트를 검사할 때 systemd-udevd 데몬이 많은 양의 CPU 시간(여러 코어에서 약 20%)을 소비하는 것으로 나타났습니다. 이는 이상한 동작이므로 이유를 알아내야 합니다. Systemd-udevd는 uevent와 함께 작동하므로 우리는 이를 통해 살펴보기로 결정했습니다. udevadm 모니터. 시스템의 각 블록 장치에 대해 많은 수의 변경 이벤트가 발생한 것으로 나타났습니다. 이는 매우 특이한 현상이므로 무엇이 이러한 모든 이벤트를 생성하는지 살펴봐야 합니다.

BCC 툴킷 사용

우리가 이미 알아낸 바와 같이 커널(및 시스템 호출의 ceph 데몬)은 다음 작업에 많은 시간을 소비합니다. generic_make_request(). 이 기능의 속도를 측정해 보겠습니다. 안에 BCC 이미 훌륭한 유틸리티가 있습니다 - 기능. 출력 사이에 1초 간격으로 PID로 데몬을 추적하고 결과를 밀리초 단위로 출력합니다.

이 기능은 일반적으로 빠르게 작동합니다. 그것이 하는 일은 요청을 장치 드라이버 큐에 전달하는 것뿐입니다.

캐시 실제로 세 개의 디스크로 구성된 복잡한 장치입니다.

• 백업 장치(캐시된 디스크), 이 경우에는 느린 HDD입니다.
• 캐싱 장치(캐싱 디스크), 여기서는 NVMe 장치의 한 파티션입니다.
• 애플리케이션이 실행되는 bcache 가상 장치입니다.

요청 전송 속도가 느리다는 것은 알고 있습니다. 하지만 이러한 장치 중 어떤 장치에 대한 것일까요? 이 문제는 잠시 후에 다루겠습니다.

이제 우리는 uevent가 문제를 일으킬 가능성이 있다는 것을 알고 있습니다. 세대의 원인을 정확히 찾는 것은 그리 쉬운 일이 아닙니다. 이것이 주기적으로 실행되는 일종의 소프트웨어라고 가정해 보겠습니다. 스크립트를 사용하여 시스템에서 어떤 종류의 소프트웨어가 실행되는지 살펴 보겠습니다. 임원 같은 것에서 BCC 유틸리티 키트. 이를 실행하고 출력을 파일로 보내겠습니다.

예를 들면 다음과 같습니다.

/usr/share/bcc/tools/execsnoop  | tee ./execdump

여기서 execsnoop의 전체 출력을 표시하지는 않지만 관심 있는 한 줄은 다음과 같습니다.

sh 1764905 5802 0 sudo arcconf getconfig 1 AD | grep Temperature | awk -F '[:/]' '{print $2}' | sed 's/^ ([0-9]*) C.*/1/'

세 번째 열은 프로세스의 PPID(상위 PID)입니다. PID 5802의 프로세스는 모니터링 시스템의 스레드 중 하나로 밝혀졌습니다. 모니터링 시스템의 구성을 확인할 때 잘못된 매개변수가 발견되었습니다. HBA 어댑터의 온도는 30초마다 측정되는데, 이는 필요한 것보다 훨씬 더 자주 측정됩니다. 확인 간격을 더 긴 것으로 변경한 후 이 호스트의 요청 처리 대기 시간이 더 이상 다른 호스트에 비해 두드러지지 않는 것으로 나타났습니다.

그러나 bcache 장치가 왜 그렇게 느린지는 여전히 불분명합니다. 동일한 구성의 테스트 플랫폼을 준비하고 bcache에서 fio를 실행하고, 주기적으로 udevadm 트리거를 실행하여 uevent를 생성하여 문제를 재현해 보았습니다.

BCC 기반 도구 작성

가장 느린 호출을 추적하고 표시하는 간단한 유틸리티를 작성해 보겠습니다. generic_make_request(). 또한 이 함수가 호출된 드라이브의 이름에도 관심이 있습니다.

계획은 간단합니다.

• 등록하다 kprobe 에 generic_make_request():
  • 디스크 이름을 함수 인수를 통해 액세스할 수 있는 메모리에 저장합니다.
  • 타임스탬프를 저장합니다.

• 등록하다 크레트프로브 복귀를 위해 generic_make_request():
  • 현재 타임스탬프를 얻습니다.
  • 저장된 타임스탬프를 찾아 현재 타임스탬프와 비교합니다.
  • 결과가 지정된 것보다 크면 저장된 디스크 이름을 찾아서 터미널에 표시합니다.

Kprobes и 크레트프로브 중단점 메커니즘을 사용하여 즉시 함수 코드를 변경합니다. 당신은 읽을 수있다 문서 и 좋은 이 주제에 관한 기사. 다양한 유틸리티의 코드를 살펴보면 BCC, 그러면 동일한 구조를 가지고 있음을 알 수 있습니다. 따라서 이 기사에서는 스크립트 인수 구문 분석을 건너뛰고 BPF 프로그램 자체로 넘어갑니다.

Python 스크립트 내부의 eBPF 텍스트는 다음과 같습니다.

bpf_text = “”” # Here will be the bpf program code “””

함수 간에 데이터를 교환하기 위해 eBPF 프로그램은 다음을 사용합니다. 해시 테이블. 우리도 똑같이 할 것입니다. 프로세스 PID를 키로 사용하고 구조를 값으로 정의합니다.

struct data_t {
	u64 pid;
	u64 ts;
	char comm[TASK_COMM_LEN];
	u64 lat;
	char disk[DISK_NAME_LEN];
};

BPF_HASH(p, u64, struct data_t);
BPF_PERF_OUTPUT(events);

여기에 해시 테이블을 등록합니다. p, 키 유형 포함 u64 유형 값 구조체 data_t. 이 테이블은 BPF 프로그램의 맥락에서 사용할 수 있습니다. BPF_PERF_OUTPUT 매크로는 다음과 같은 다른 테이블을 등록합니다. 이벤트, 이는 다음 용도로 사용됩니다. 데이터 전송 사용자 공간으로.

함수 호출과 함수 반환 사이 또는 다른 함수 호출 사이의 지연을 측정할 때 수신된 데이터가 동일한 컨텍스트에 속해야 한다는 점을 고려해야 합니다. 즉, 기능의 병렬 실행 가능성을 기억해야 합니다. 우리는 한 프로세스의 컨텍스트에서 함수를 호출하고 다른 프로세스의 컨텍스트에서 해당 함수에서 반환하는 사이의 대기 시간을 측정할 수 있지만 이는 쓸모가 없을 가능성이 높습니다. 여기에 대한 좋은 예는 다음과 같습니다. 생체잠복성 유틸리티, 여기서 해시 테이블 키는 다음을 가리키는 포인터로 설정됩니다. 구조체 요청, 이는 하나의 디스크 요청을 반영합니다.

다음으로, 연구 중인 함수가 호출될 때 실행될 코드를 작성해야 합니다.

void start(struct pt_regs *ctx, struct bio *bio) {
	u64 pid = bpf_get_current_pid_tgid();
	struct data_t data = {};
	u64 ts = bpf_ktime_get_ns();
	data.pid = pid;
	data.ts = ts;
	bpf_probe_read_str(&data.disk, sizeof(data.disk), (void*)bio->bi_disk->disk_name);
	p.update(&pid, &data);
}

여기서 호출된 함수의 첫 번째 인수는 두 번째 인수로 대체됩니다. generic_make_request(). 그런 다음 작업 중인 프로세스의 PID와 나노초 단위의 현재 타임스탬프를 얻습니다. 우리는 새로 선택한 항목에 모든 것을 기록합니다. 구조체 data_t 데이터. 구조에서 디스크 이름을 얻습니다. 바이오, 호출할 때 전달됩니다. generic_make_request(), 동일한 구조로 저장 데이터. 마지막 단계는 앞서 언급한 해시 테이블에 항목을 추가하는 것입니다.

다음 함수는 반환 시 호출됩니다. generic_make_request():

void stop(struct pt_regs *ctx) {
    u64 pid = bpf_get_current_pid_tgid();
    u64 ts = bpf_ktime_get_ns();
    struct data_t* data = p.lookup(&pid);
    if (data != 0 && data->ts > 0) {
        bpf_get_current_comm(&data->comm, sizeof(data->comm));
        data->lat = (ts - data->ts)/1000;
        if (data->lat > MIN_US) {
            FACTOR
            data->pid >>= 32;
            events.perf_submit(ctx, data, sizeof(struct data_t));
        }
        p.delete(&pid);
    }
}

이 함수는 이전 함수와 유사합니다. 프로세스의 PID와 타임스탬프를 알아내지만 새 데이터 구조에 메모리를 할당하지는 않습니다. 대신, 키 == 현재 PID를 사용하여 이미 존재하는 구조에 대한 해시 테이블을 검색합니다. 구조가 발견되면 실행 중인 프로세스의 이름을 찾아서 추가합니다.

스레드 GID를 얻으려면 여기서 사용하는 이진 시프트가 필요합니다. 저것들. 작업 중인 컨텍스트에서 스레드를 시작한 기본 프로세스의 PID입니다. 우리가 호출하는 함수 bpf_get_current_pid_tgid() 스레드의 GID와 PID를 모두 단일 64비트 값으로 반환합니다.

터미널로 출력할 때 현재 스레드에는 관심이 없지만 기본 프로세스에는 관심이 있습니다. 결과 지연을 주어진 임계값과 비교한 후 구조를 전달합니다. 데이터 테이블을 통해 사용자 공간으로 이벤트, 그 후에 항목을 삭제합니다. p.

이 코드를 로드할 Python 스크립트에서 MIN_US 및 FACTOR를 지연 임계값 및 시간 단위로 바꿔야 하며, 이를 인수를 통해 전달합니다.

bpf_text = bpf_text.replace('MIN_US',str(min_usec))
if args.milliseconds:
	bpf_text = bpf_text.replace('FACTOR','data->lat /= 1000;')
	label = "msec"
else:
	bpf_text = bpf_text.replace('FACTOR','')
	label = "usec"

이제 다음을 통해 BPF 프로그램을 준비해야 합니다. BPF 매크로 샘플을 등록합니다.

b = BPF(text=bpf_text)
b.attach_kprobe(event="generic_make_request",fn_name="start")
b.attach_kretprobe(event="generic_make_request",fn_name="stop")

우리는 또한 결정해야 할 것입니다 구조체 data_t 그렇지 않으면 아무것도 읽을 수 없습니다:

TASK_COMM_LEN = 16	# linux/sched.h
DISK_NAME_LEN = 32	# linux/genhd.h
class Data(ct.Structure):
	_fields_ = [("pid", ct.c_ulonglong),
            	("ts", ct.c_ulonglong),
            	("comm", ct.c_char * TASK_COMM_LEN),
            	("lat", ct.c_ulonglong),
            	("disk",ct.c_char * DISK_NAME_LEN)]

마지막 단계는 터미널에 데이터를 출력하는 것입니다.

def print_event(cpu, data, size):
    global start
    event = ct.cast(data, ct.POINTER(Data)).contents
    if start == 0:
        start = event.ts
    time_s = (float(event.ts - start)) / 1000000000
    print("%-18.9f %-16s %-6d   %-1s %s   %s" % (time_s, event.comm, event.pid, event.lat, label, event.disk))

b["events"].open_perf_buffer(print_event)
# format output
start = 0
while 1:
    try:
        b.perf_buffer_poll()
    except KeyboardInterrupt:
        exit()

스크립트 자체는 다음에서 사용할 수 있습니다. GItHub. fio가 실행되고 bcache에 쓰고 udevadm 모니터를 호출하는 테스트 플랫폼에서 실행해 보겠습니다.

마지막으로! 이제 우리는 지연된 bcache 장치처럼 보였지만 실제로는 지연된 호출임을 알 수 있습니다. generic_make_request() 캐시된 디스크의 경우.

커널을 자세히 살펴보세요

요청 전송 중에 속도가 느려지는 것은 정확히 무엇입니까? 요청 회계가 시작되기 전에도 지연이 발생하는 것을 볼 수 있습니다. 이에 대한 추가 통계 출력에 대한 특정 요청(/proc/diskstats 또는 iostat)에 대한 설명이 아직 시작되지 않았습니다. 이는 문제를 재현하는 동안 iostat를 실행하여 쉽게 확인할 수 있습니다. BCC 스크립트 생체 대기 시간, 요청 회계의 시작과 끝을 기준으로 합니다. 이러한 유틸리티 중 어느 것도 캐시된 디스크에 대한 요청에 대한 문제를 표시하지 않습니다.

기능을 살펴보면 generic_make_request(), 그러면 요청이 계산을 시작하기 전에 두 개의 함수가 더 호출되는 것을 볼 수 있습니다. 첫 번째 - generic_make_request_checks(), 디스크 설정과 관련된 요청의 적법성을 확인합니다. 두번째 - blk_queue_enter(), 흥미로운 도전 과제가 있습니다. wait_event_interruptible():

ret = wait_event_interruptible(q->mq_freeze_wq,
	(atomic_read(&q->mq_freeze_depth) == 0 &&
	(preempt || !blk_queue_preempt_only(q))) ||
	blk_queue_dying(q));

그 안에서 커널은 대기열이 고정 해제될 때까지 기다립니다. 지연을 측정해보자 blk_queue_enter():

~# /usr/share/bcc/tools/funclatency  blk_queue_enter -i 1 -m               	 
Tracing 1 functions for "blk_queue_enter"... Hit Ctrl-C to end.

 	msecs           	: count 	distribution
     	0 -> 1      	: 341  	|****************************************|

 	msecs           	: count 	distribution
     	0 -> 1      	: 316  	|****************************************|

 	msecs           	: count 	distribution
     	0 -> 1      	: 255  	|****************************************|
     	2 -> 3      	: 0    	|                                    	|
     	4 -> 7      	: 0    	|                                    	|
     	8 -> 15     	: 1    	|                                    	|

우리는 해결책에 가까워진 것 같습니다. 대기열을 고정/고정 해제하는 데 사용되는 기능은 다음과 같습니다. blk_mq_freeze_queue и blk_mq_unfreeze_queue. 이 대기열의 요청에 잠재적으로 위험할 수 있는 요청 대기열 설정을 변경해야 할 때 사용됩니다. 전화할 때 blk_mq_freeze_queue() 함수 blk_freeze_queue_start() 카운터가 증가합니다 q->mq_freeze_깊이. 그 후, 커널은 대기열이 비워질 때까지 기다립니다. blk_mq_freeze_queue_wait().

이 대기열을 지우는 데 걸리는 시간은 커널이 대기열에 있는 모든 작업이 완료될 때까지 기다리기 때문에 디스크 대기 시간과 동일합니다. 대기열이 비어 있으면 설정 변경 사항이 적용됩니다. 그 후에는 blk_mq_unfreeze_queue(), 카운터 감소 동결_깊이.

이제 우리는 상황을 바로잡을 만큼 충분히 알고 있습니다. udevadm Trigger 명령을 사용하면 블록 장치에 대한 설정이 적용됩니다. 이러한 설정은 udev 규칙에 설명되어 있습니다. sysfs를 통해 설정을 변경하거나 커널 소스 코드를 살펴봄으로써 대기열을 정지시키는 설정을 찾을 수 있습니다. BCC 유틸리티를 사용해 볼 수도 있습니다. 더듬다, 터미널에 대한 각 호출에 대한 커널 및 사용자 공간 스택 추적을 출력합니다. blk_freeze_queue예 :

~# /usr/share/bcc/tools/trace blk_freeze_queue -K -U
PID 	TID 	COMM        	FUNC        	 
3809642 3809642 systemd-udevd   blk_freeze_queue
    	blk_freeze_queue+0x1 [kernel]
    	elevator_switch+0x29 [kernel]
    	elv_iosched_store+0x197 [kernel]
    	queue_attr_store+0x5c [kernel]
    	sysfs_kf_write+0x3c [kernel]
    	kernfs_fop_write+0x125 [kernel]
    	__vfs_write+0x1b [kernel]
    	vfs_write+0xb8 [kernel]
    	sys_write+0x55 [kernel]
    	do_syscall_64+0x73 [kernel]
    	entry_SYSCALL_64_after_hwframe+0x3d [kernel]
    	__write_nocancel+0x7 [libc-2.23.so]
    	[unknown]

3809631 3809631 systemd-udevd   blk_freeze_queue
    	blk_freeze_queue+0x1 [kernel]
    	queue_requests_store+0xb6 [kernel]
    	queue_attr_store+0x5c [kernel]
    	sysfs_kf_write+0x3c [kernel]
    	kernfs_fop_write+0x125 [kernel]
    	__vfs_write+0x1b [kernel]
    	vfs_write+0xb8 [kernel]
    	sys_write+0x55 [kernel]
    	do_syscall_64+0x73 [kernel]
    	entry_SYSCALL_64_after_hwframe+0x3d [kernel]
    	__write_nocancel+0x7 [libc-2.23.so]
    	[unknown]

Udev 규칙은 거의 변경되지 않으며 일반적으로 이는 통제된 방식으로 발생합니다. 따라서 이미 설정된 값을 적용해도 애플리케이션에서 디스크로 요청을 전송하는 데 지연이 급증하는 것을 알 수 있습니다. 물론 디스크 구성에 변경 사항이 없을 때(예: 장치가 마운트/연결 해제되지 않은 경우) udev 이벤트를 생성하는 것은 좋은 방법이 아닙니다. 그러나 커널이 불필요한 작업을 수행하지 않고 필요하지 않은 경우 요청 대기열을 동결하도록 도울 수 있습니다. 세 작은 저지르다 상황을 바로잡아라.

결론

eBPF는 매우 유연하고 강력한 도구입니다. 기사에서 우리는 하나의 실제 사례를 살펴보고 수행할 수 있는 작업의 작은 부분을 시연했습니다. BCC 유틸리티 개발에 관심이 있다면 한 번 살펴보는 것이 좋습니다. 공식 튜토리얼, 기본 사항을 잘 설명합니다.

eBPF를 기반으로 하는 다른 흥미로운 디버깅 및 프로파일링 도구가 있습니다. 그들 중 하나 - bpftrace를 사용하면 awk와 유사한 언어로 강력한 한 줄짜리 프로그램과 작은 프로그램을 작성할 수 있습니다. 또 다른 - ebpf_exporter를 사용하면 Prometheus 서버에 직접 낮은 수준의 고해상도 측정항목을 수집할 수 있으며 나중에 아름다운 시각화와 알림까지 받을 수 있습니다.

출처 : habr.com