병렬로 추론요청시 예상되는 총 추론시간보다 오래 걸리는 이슈

[kh3654po]

현재 시나리오에서 xavier에 yolo모델에대한 요청을 보낼때, 10초 동안 매초 평균 50개의 요청을 보낸다. 이때 한 요청을 처리하는데 걸리는 평균 시간이 0.1초이다. 예상되는 총 추론시간은 10초대인데 실제 총 추론 시간은 47초 가량나온다. 이를 해결해야한다.

sleep 문제로 여겨짐 -> sched 모듈 사용해볼것

[kh3654po]

• sched module scheduler에 enter(딜레이, 우선순위, 함수, 파라미터)로 함수를 등록하면 해당 함수를 딜레이 시간뒤에 실행시켜주는데 병렬로 처리하지 않습니다. 아래 코드는 0.02초 마다 현재 시간을 출력합니다.

import sched
import time

s = sched.scheduler()
start_time = time.time()

def print_cur_time(idx, start):
    print(f'[{idx}] cur time = {time.time() - start}')
    time.sleep(1)

for i in range(500):
    s.enter(0.02, 1, print_cur_time, (i, start_time,))

s.run()

병렬 처리하는지 확인하기 위해 함수 내부에서 1초의 슬립시간을 주는데 출력내용은 아래와 같습니다.

[0] cur time = 0.025021076202392578
[1] cur time = 1.0283100605010986
[2] cur time = 2.0334370136260986
[3] cur time = 3.0354549884796143
[4] cur time = 4.0379719734191895
[5] cur time = 5.04064416885376

이 모듈을 사용해서 시나리오를 실험해본 결과 기존 47초 걸렸던 것이 85초 걸린것으로 나옵니다. 다른방법도 찾아보겠습니다

[kh3654po]

• sleep 없이 추론 요청을 보냈을 때 추론을 시작한 시간을 출력한 결과가 아래와 같습니다.
• [13] 요청까지는 요청사이의 시간이 0.00x초마다 출력이 되는데 이후 부터는 0.1초 이상이 걸립니다. 계속해서 출력해서 확인해보니 이전 요청시간과 비교하여 0.7초 후에 실행된 결과도 있습니다.
• sleep의 문제뿐만 아니라 thread를 10개 이상 실행시키면 오버헤드가 발생하는것 같습니다.

[0] req start: 1685452045.4115615
[1] req start: 1685452045.4121022
[2] req start: 1685452045.413509
[3] req start: 1685452045.4137502
[4] req start: 1685452045.41601
[5] req start: 1685452045.4168396
[6] req start: 1685452045.4177065
[7] req start: 1685452045.420746
[8] req start: 1685452045.4221463
[9] req start: 1685452045.4225512
[10] req start: 1685452045.4231281
[11] req start: 1685452045.4237332
[12] req start: 1685452045.424365
[13] req start: 1685452045.425831
[14] req start: 1685452045.5506392
[15] req start: 1685452045.7485943
[16] req start: 1685452046.3975217
[17] req start: 1685452046.5334008

• 요청을 처리하는 동안 master 장비의 자원 사용량 변화

  • 요청 처리전

    

  • 요청 처리중

    

  • 메모리는 300MB, cpu는 일부분 사용하는 것을 볼 수 있고 여유가 있는 것을 확인했습니다.

[kmu-leeky]

오케이. 석현아. 그렇다면 이 문제를 분리해서 하나씩 보는게 좋겠다. 지금은 요청을 보내는 쓰레드를 동시에 생성하고 있는데, 원인을 분석한다면

1. 별다른 작업없이 출력만 하는 쓰레드를 50개 연속으로 생성하면서 시간을 출력해서 지체가 있는지 보기
2. 지금처럼 요청을 보내는 쓰레드를 50개 연속으로 생성하면서 시간을 출력해보기

2번을 할때 지금 처럼 전체 코드를 사용하지 말고 아무것도 없는 새로운 코드를 만들어서 엣지 서버에 호출을 하게끔 시도해보는게 필요할것 같아. 지금 코드가 복잡해져서 불필요한 오버헤드가 포함될수 있으니.

[kh3654po]

교수님 말씀대로 실험을 진행해보다가 해결방법을 찾은것 같습니다. 현재 매 요청마다 tf server에 요청을 보내기 위한 preprocessing을 하는데 여기서 오버헤드가 발생합니다. 매 요청마다 preprocessing을 하는것이 아니라 preprocessing을 미리한 데이터를 가지고 50개의 요청을 병렬로 보내보니 딜레이가 보내졌습니다. 이를 위해서 기존 코드를 수정해야하는데 수정하고 테스트 진행후 공유드리겠습니다. 다음은 2번을 테스트하던중 preprocessing을 각 요청마다가 아닌 한번만 실행하도록 수정후 50개의 요청을 보내도록 테스트해본 결과입니다. 각 요청사이의 시간은 0.01초 정도였습니다.

[0] start: 1685539566.3231869
[1] start: 1685539566.3236895
[2] start: 1685539566.3246057
[3] start: 1685539566.3250432
[4] start: 1685539566.3284254
[5] start: 1685539566.3380067
[6] start: 1685539566.340718
[7] start: 1685539566.3438148
[8] start: 1685539566.346235
[9] start: 1685539566.3464549
[10] start: 1685539566.3487616
[11] start: 1685539566.3549814
[12] start: 1685539566.358828
[13] start: 1685539566.3593504
[14] start: 1685539566.36233
[15] start: 1685539566.3627093
...

[kmu-leeky]

오케이. 석현아 발견했다니 다행이다. 결국 preprocessing 을 여러 쓰레드에서 동시에 실행하다보니 오버헤드가 추가되었구나 ㅎㅎ 잘했다. 코드 수정 후 실험 진행해보자.

[kh3654po]

코드 수정후 테스트 해보았습니다. 테스트 할 때는 기존 코드와 같이 매초 요청을 보낼때 (1/요청량)만큼 슬립을 주도록 하였습니다. 그리고 각 초마다 요청량을 다 보냈을 때 실제로 얼마나 걸렸는지 출력하도록 하였습니다.

1초대 모든 요청전송 완료시간 : 1.050424337387085
2초대 모든 요청전송 완료시간 : 1.0515761375427246
3초대 모든 요청전송 완료시간 : 1.0500853061676025
4초대 모든 요청전송 완료시간 : 1.0548288822174072
5초대 모든 요청전송 완료시간 : 1.0640850067138672
6초대 모든 요청전송 완료시간 : 1.0724146366119385
7초대 모든 요청전송 완료시간 : 1.0653228759765625
8초대 모든 요청전송 완료시간 : 1.0628080368041992
9초대 모든 요청전송 완료시간 : 1.0736918449401855
10초대 모든 요청전송 완료시간 : 1.0659704208374023

preprocessing 오버헤드가 원인이 맞았던것 같습니다. 이 코드를 가지고 다시 테스트 해보겠습니다.

[kmu-leeky]

오케이. 석현아 잘 수정했다. 이정도라면 그냥 sleep 을 줘서 실험을 진행해도 되겠다.