[Profile] GPU profile을 통한 병목 진단 및 개선

오늘은 deep learning 모델을 학습 시킬때 GPU 사용율이 저조한 경우 이 현상의 원이이 뭐고

어떻게 개선 할수 있는지에 대해 포스팅을 해보고자 한다. 어디 까지나 필자의 접근 법이고 완벽한 답은 아니다.. 

 

개발 환경:

frame work: pytorch 1.7

os: ubuntu 20.04

training env: multi gpu(distributed module 사용)

 

목차:

1. 현상

2. 원인 분석 및 profile

3. 개선

 

현상

학습 하는 네트워크는 CNN 기반의 segmentation 네트워크 였고 학습 데이터는 이미지 약 7만장 이상이었다. 

초기 input pipe line은 image-annotation file pair 를 읽어 들이는 원시적인 형태로 되어있었다.

annotation file에는 polygon 형태의 segmentation label 정보가 저장되어 있어서 이 정보를 mask image로 바꾸어 NAS에 저장해두었다.

디렉토리 구조는 아래와 같다.

Fig 1. 초기 디렉토리 구조

 

v100 tensor core gpu 로 위 상태 그대로 학습을 진행 했을때 배치 사이즈 48 기준 약 25분이 걸리는 신기한 현상이 발생했다.

 gpu 사용율은 아래 그림 Fig 2. 처럼 100% -> 9% -> 90% -> 10%->0% -> 100% 과 사용율의 등락율이 굉장히 커보였다. 

아래 그림은 위 상황에 대한 캡쳐 본으로 아래 명령을 입력해 확인할 수 있다.

watch -n 1 nvidia-smi

Fig 2. gpu 사용율(Volatile GPU-Util 항목)을 보면 위 그림에서 100% 사용하다가 아래 그림에서는 13%,0%,0%,100%로 사용율의 등락률이 큰 것을 확인할 수 있다.

 

원인 분석 및 Profile

위와 같은 현상이 나타나면 대부분 원인은 둘 중 하나다. 

1. 파일이 저장된 위치가 NAS 니까 사용자가 많아 대역폭 확보가 안되어 File I/O가 병목의 원인이거나 
2. I/O 가 문제가 아니라면 CPU 연산이 많아 병목의 원이이 되는 경우다.

위 현상을 진단할 수 있는 방법은 크게 2가지이다. 

• iftop 을 이용해 File I/O speed를 체크해 보는 방법이 있고(엄밀히 말하면 network를 통한 file transfer speed)
• htop 을 이용해 CPU 사용량을 체크해 보는 방법이 있다.

나는 sudo 권한이 없어서 1번 방법을 쓸 수 없어서 htop을 이용해 진단을 했다. 

방법은 간단하고 나름 합리적이고 크게 두 가지 케이스로 나눠 진다. 

1. htop을 사용해 CPU 사용량을 모니터링했을 때 CPU 코어의 사용율이 저조 하고 데이터 로더 프로세스 상태가 D(uninterruptible sleep-usually I/O) 인 경우가 많다면 File I/O가 병목인 경우가 대부분이다. 
2. CPU 코어의 사용율이 거의 100%에 가깝고 데이 로더 프로세스 상태가 D인 경우가 거의 없다면 CPU 연산이 병목의 원인인 경우가 많다.

본인의 경우가 케이스 2. 에 해당 한다면 GPU 프로파일을 한번쯤은 해보는게 좋다. 혹시 라도 네트워크의 구조 또는 loss의 구현이 비효율적으로 되어있어 GPU 사용율이 떨어질 가능 성이 있기 때문이다. 

 

본인의 경우에는 케이스 2에 해당되어 GPU 프로파일 까지 진행했었다. 

gpu프로파일에 nvidia NSIGHT SYSTEMS PROFILE을 이용했다. 

사용방법은 매우 간하며 아래와 같은 명령어를 사용하면 된다. 

nsys profile –t cuda,osrt,nvtx,cudnn,cublas -o baseline.qdstrm -w true python your_train_script.py

사용시 주의할 점은 반드시 <your_train_script.py> 가 의미 있는 유한 시간안에 정상 종료 해야 한다는 것이다. 

무슨 말이냐면 아래 코드 처럼 train iteration횟 수를 유한 시간안에 끝날 수 있는 횟수로 제한 하는 것이 필요 하다는 것이다. 

for i in range(10):
    nvtx.range_push('data loading')
    batch = next(dataloader)
    nvtx.range_pop()

    for key, data in batch.items():
    	batch[key]=data.cuda()

    nvtx.range_push('Forward pass')
    nvtx.range_push('Batch')
    out = model.forward(image.cuda())
    loss = getLoss(out)
    nvtx.range_pop()
    nvtx.range_pop()
    nvtx.range_push('backward pass')
    loss.backward()
    optimizer.step()
    optimizer.zero_grad()
    nvtx.range_pop()

nvtx.range_push(), nvtx.range_pop() 등은 프로파일 결과 파일을 보기 편하게 해주는 역할을 해준다. 

NSIGHT (GPU driver 설치시 대부분 같이 설치 된다.)을 이용해 프로파일 결과 파일을 열면 아래와 같은 그래프를 볼 수 있다.

Fig 3. GPU 프로파일 결과

Fig 3. 의 붉은 박스 부분을 보면 NVTX 항목에 data loding, Batch, backward, data loading, batch, backward 라는 부분을 볼 수 있다. 각 항목은 위 예제 코드에서 직관 적으로 알수 있듯이 각각 data loading에 걸리는 시간, batch의 forward pass 연산에 걸리는 시간, backward pass에 걸리는 시간의 포션을 나타낸다.

 

그래프에서 확인 가능 하듯, data loading이 차지 하는 시간이 절대적으로 많다.

data loading에서 augmentation 을 하는데 이 연산은 cpu를 활용하고 gpu 연산에 비에 이 cpu 연산이 오래 걸려 gpu가 처리할 데이터를 꾸준히 공급하지 못하는 것이 낮은 gpu 사용율의 원인이었다. 이때 GPU 사용율을 높이고자 한다면 이 GPU starvation 의 간격을 최대한 줄이거나 더 나아가 GPU 연산부와 CPU 연산부가 서로 겹치도록 연산 파이프라인을 구축하는 것이 최선이다. 

 

이렇게 GPU 프로파일을 하고 보니 현재 문제가 되는 부분은 확실히 data loading 이다.

FILE I/O는 거의 문제가 안되고 있으니

CPU 연산이 절대적으로 많거나 비효율 적으로 연산을 하고 있는 것으로 해석된다. 

 

다음으로 data loader 내부에서 시간을 많이 잡아 먹는 부분을 특정 정하기 위해 python profile을 수행했다. 

cProfile이라는 python 모듈을 이용했는데 결과 캡쳐하는걸 깜박해... 사진은 생략한다. 

가슴아프게도 결과는 data augmentation이 약 40%를 차지 했고 

사용한 augmentation 은 flip, translation, rotation, gaussian noise, hue transform, shadow adding 등이다.

augmentation 후 약 3개의 함수에서  loss 계산에 필요한 특정 heat map, offset map을 만들기 위한 작업을 진행하는데

이 부분이 약 40%의 시간을 차지 했다. 나열하고 CPU연산이 많긴 하다. 

 

 

개선

augmentation 은 nvidia DALI를 사용하고자 했지만 아직 구현을 완료 하지 못했다. (40%의 성능 향상을 아직은 이루지 못했다는 소리다- 이 부분은 향후 과제다. DALI 버전을 완료 하면 내용을 보완해야겠다.)

 

나머지 40%의 개선을 이루기 위해 loss 계산에 필요핸 map 들을 만드는 부분을 수정했는데

결과는 이미지 1장당 약 4ms 걸리던 작업을 0.4ms 정도 걸리게 끔 구현을 다시 했다. 

 

사실 엄청난 걸한거 같지만 기존 코드가 말도 안되게 비효율 적인 구조를 가지고 있었다. 

numpy array를 처리 하는데 형태가 (n,1,2) 인 포인트의 좌표 를 담고 있는 배열을 (n 개의 (x,y) 좌표 값을 가진 배열)

python for문을 이용해 순회 하며 offset map 과 heat map 등을 만들고 있었다. 

for 문을 없에고 numpy indexing 과 matrix 계산으로 바꾸니 약 1/10 로 속도가 개선되었다. 

아래 그림은 수정한 코드에서 CPU 사용율을 캡쳐 한것이다. 

Fig 4. 개선 버전의 GPU profile 결과

Fig 5 를 Fig 3과 비교해보면 data loading 시간이 분명 줄었다. 27.xx 초 에서 10.372로 줄었으니 줄긴 많이 줄었다. 실제로

한 epoch 학습 시키는데  걸리는 시간도 50%가량 줄었다. (data loader가 10초 씩이나 걸리는게 말이 안된다고 생각 하겠지만 프로파일러가 샘플링을 하기 때문에 저렇게 말도 안되는 시간이 나온거다. 실제 몇초 인지 수치 보다 gpu 연산 시간을 나타내는 Batch 의 길이와 data loading의 길이 비율 차에 집중해서 보길 바란다.) 

 

여기까진 좋았다 원하던 결과다 다만 위와 같이 개선한 후에도 여전히 data loading 시간이 gpu의 forward + backward pass 연산 시간에 비해 더 많은 시간을 소모 한다. 그 결과 당연히 gpu 사용률의 등락 폭은 줄어 들지 않았다. 

아래 그림을 보면 이 분석을 시작한 현상이 그대로 남아 있음을 알 수 있다. 

Fig 5. data loader 코드 개선 버전의 gpu 사용률 

그래서 다시 htop로 cpu 사용률 모리터링을 해보니 아래 그림 Fig 6. 과 같이 cpu가 100%일을 하고 있지는 않다. 

Fig 5. CPU 바운드 원인 코드 개선 버전의 cpu 사용율

 

이전 섹션인 '원인 분석 및 profile'에서 CPU 가 거의 항상 100%사용 중임에도 불구하고

GPU 사용율이 낮았기 때문에 FILE i/o가 병목 현상의 원인은 아닐거라고 생각했다.

 그런데 코드를 개선 하고 나니 CPU 사용율은 절반 수준으로 낮아졌으나 data loading 시간은 여전히 오래 걸린다. 

 

여기서 의문이 들었다.

cpu가 저렇게 50~60%정도의 사용율을 보인다는 것을 File I/o의 문제라고 볼 수 있을까?

File I/o가 문제라면 cpu core의 사용율이 낮은게 아니라  말그대로 놀고 있는 0~1%의 사용율이 나와야 하는거 아닐까?

 

그럼 저렇게 cpu 사용율이 낮아졌는데 역전히 data loader가 batch를 생산하는데 시간이 오래 걸리는 원인이 뭘까?

 

좀더 분석을 해봐야겠다.