추론요청일 쌓이는데 추론시간은 짧아지는 이슈

[kh3654po]

10초 동안 요청을 보낼 때 각장비에서 요청을 다 처리하지 못해 요청이 쌓이고 그로인해 추론시간이 점점 증가한다. 하지만 10초 중 7초에서 최고점을 찍고 8~10초는 추론시간이 줄어드는 현상이 있다. 매초 요청을 다 처리하지 못한다면 추론시간이 점점 증가해야하는데 줄어드는 이유를 파악해야한다.

[kh3654po]

• 초당 평균 50개의 mobilenet v1 요청을 보내보았을 때 결과입니다.

• inference time info를 보면 평균 추론시간 (avg)가 점점 증가하다가 8초부터 점점 떨어지는데 완료되지 않은 요청량을 보면 점점 증가함을 볼 수 있습니다. 이에대해 아직 원인파악을 하지못했습니다.

• (50,0,0,0)
  1초대 완료되지 않은 요청량: 20/48
  2초대 완료되지 않은 요청량: 50/104
  3초대 완료되지 않은 요청량: 87/163
  4초대 완료되지 않은 요청량: 116/220
  5초대 완료되지 않은 요청량: 136/267
  6초대 완료되지 않은 요청량: 161/321
  7초대 완료되지 않은 요청량: 177/366
  8초대 완료되지 않은 요청량: 205/420
  9초대 완료되지 않은 요청량: 213/460
  10초대 완료되지 않은 요청량: 223/499

  total request num: 499
  total inference time 14.026915311813354

  ---

  inference time info (each argument is info about requests per sec)

  [1] reqeust num per sec: 48
  [1] avg: 0.47826547423998517
  [1] min: 0.10318112373352051
  [1] max: 1.0406076908111572
  [1] 25%: 0.27028989791870117
  [1] 50%: 0.39719414710998535
  [1] 75%: 0.645216703414917

  [2] reqeust num per sec: 56
  [2] avg: 1.6692972353526525
  [2] min: 0.18375325202941895
  [2] max: 3.7125141620635986
  [2] 25%: 1.0030832290649414
  [2] 50%: 1.8272631168365479
  [2] 75%: 2.161561965942383

  [3] reqeust num per sec: 59
  [3] avg: 2.837464102243973
  [3] min: 0.501023530960083
  [3] max: 7.025740146636963
  [3] 25%: 1.9583628177642822
  [3] 50%: 2.813952684402466
  [3] 75%: 3.5670623779296875

  [4] reqeust num per sec: 57
  [4] avg: 3.9243796290012827
  [4] min: 2.2553000450134277
  [4] max: 8.789379358291626
  [4] 25%: 2.724595785140991
  [4] 50%: 4.073466062545776
  [4] 75%: 4.486824989318848

  [5] reqeust num per sec: 47
  [5] avg: 4.866949898131351
  [5] min: 2.719339609146118
  [5] max: 8.975116968154907
  [5] 25%: 3.5106284618377686
  [5] 50%: 4.76103401184082
  [5] 75%: 5.661944627761841

  [6] reqeust num per sec: 54
  [6] avg: 4.926562852329678
  [6] min: 3.034287452697754
  [6] max: 7.662695407867432
  [6] 25%: 4.607053518295288
  [6] 50%: 4.9957873821258545
  [6] 75%: 5.472883224487305

  [7] reqeust num per sec: 45
  [7] avg: 5.159737941953871
  [7] min: 3.5202207565307617
  [7] max: 7.227871894836426
  [7] 25%: 4.943770885467529
  [7] 50%: 5.318434476852417
  [7] 75%: 5.5006513595581055

  [8] reqeust num per sec: 54
  [8] avg: 4.923396048722444
  [8] min: 4.054128170013428
  [8] max: 6.609808683395386
  [8] 25%: 4.708444833755493
  [8] 50%: 4.969983100891113
  [8] 75%: 5.170379400253296

  [9] reqeust num per sec: 40
  [9] avg: 4.413933730125427
  [9] min: 3.73581600189209
  [9] max: 5.6088714599609375
  [9] 25%: 4.124396085739136
  [9] 50%: 4.366491794586182
  [9] 75%: 4.611280679702759

  [10] reqeust num per sec: 39
  [10] avg: 3.6788597718263283
  [10] min: 2.8348844051361084
  [10] max: 4.5037736892700195
  [10] 25%: 3.5196752548217773
  [10] 50%: 3.641857862472534
  [10] 75%: 3.9156455993652344

[kh3654po]

• 포아송분포를 따르는 시나리오에서 요청량이 일정한 시나리오로 변경
  • (50,0,0,0)

    • xavier

      • 매초 20개 정도의 요청이 쌓이고 기존과 마찬가지로 8초대에서 부터 평균 추론시간이 감소하였습니다.

      1초대 완료되지 않은 요청량: 21/50
      2초대 완료되지 않은 요청량: 44/100
      3초대 완료되지 않은 요청량: 63/150
      4초대 완료되지 않은 요청량: 83/200
      5초대 완료되지 않은 요청량: 106/250
      6초대 완료되지 않은 요청량: 129/300
      7초대 완료되지 않은 요청량: 148/350
      8초대 완료되지 않은 요청량: 172/400
      9초대 완료되지 않은 요청량: 193/450
      10초대 완료되지 않은 요청량: 212/500

      total request num: 500
      total inference time 13.738634824752808

      ---

      inference time info (each argument is info about requests per sec)

      [1] reqeust num per sec: 50
      [1] avg: 0.6289248704910279
      [1] min: 0.1389760971069336
      [1] max: 4.19315505027771
      [1] 25%: 0.17411112785339355
      [1] 50%: 0.2563924789428711
      [1] 75%: 0.8423507213592529

      [2] reqeust num per sec: 50
      [2] avg: 1.5985187816619872
      [2] min: 0.12061595916748047
      [2] max: 4.432455778121948
      [2] 25%: 0.32967185974121094
      [2] 50%: 1.6209747791290283
      [2] 75%: 2.594975471496582

      [3] reqeust num per sec: 50
      [3] avg: 2.085795259475708
      [3] min: 0.19492673873901367
      [3] max: 7.517604112625122
      [3] 25%: 0.7540764808654785
      [3] 50%: 1.939188003540039
      [3] 75%: 3.7663357257843018

      [4] reqeust num per sec: 50
      [4] avg: 2.872449288368225
      [4] min: 0.84281325340271
      [4] max: 6.983721733093262
      [4] 25%: 1.3444104194641113
      [4] 50%: 2.619213819503784
      [4] 75%: 4.55886697769165

      [5] reqeust num per sec: 50
      [5] avg: 3.311085386276245
      [5] min: 0.8607499599456787
      [5] max: 7.13672399520874
      [5] 25%: 2.0635836124420166
      [5] 50%: 2.743483543395996
      [5] 75%: 5.171012878417969

      [6] reqeust num per sec: 50
      [6] avg: 4.065993638038635
      [6] min: 2.4948203563690186
      [6] max: 6.865135192871094
      [6] 25%: 3.008817434310913
      [6] 50%: 3.2441883087158203
      [6] 75%: 5.439632892608643

      [7] reqeust num per sec: 50
      [7] avg: 4.394706192016602
      [7] min: 3.296422243118286
      [7] max: 6.330309152603149
      [7] 25%: 3.664797782897949
      [7] 50%: 4.183825254440308
      [7] 75%: 5.214528560638428

      [8] reqeust num per sec: 50
      [8] avg: 4.599513177871704
      [8] min: 3.8408122062683105
      [8] max: 6.097996950149536
      [8] 25%: 4.052651405334473
      [8] 50%: 4.562939643859863
      [8] 75%: 5.018351793289185

      [9] reqeust num per sec: 50
      [9] avg: 4.264447350502014
      [9] min: 3.7556025981903076
      [9] max: 5.042837142944336
      [9] 25%: 3.982180595397949
      [9] 50%: 4.235296249389648
      [9] 75%: 4.529362678527832

      [10] reqeust num per sec: 50
      [10] avg: 3.642386584281921
      [10] min: 3.154942274093628
      [10] max: 4.316688537597656
      [10] 25%: 3.3854031562805176
      [10] 50%: 3.5848145484924316
      [10] 75%: 3.9083292484283447

[kh3654po]

하드웨어 모니터링

• htop으로 쓰레드의 개수를 측정해보았습니다. 컨테이너 이미지(tf server)를 실행하기 전에는 160개정도였던 것이 실행 후 1240개까지 증가하였습니다.
• tf server 옵션중 rest_api_num_threads가 있는데 이는 rest로 요청을 받을 시 쓰레드를 몇개 생성할 것인가에 대한 설정옵션인데 이 값이 1000이었을 때 위와 같이 증가하였습니다.
• 이 옵션을 1로 바꾼후 다시 실행해 보았을 때 160개정도에서 240개로 증가한 것으로 보아 쓰레드 설정을 통해 쓰레드의 개수가 변화된 것을 확인하였습니다.
• 매초 50개의 mobilenet v1 요청을 보내는 시나리오를 가지고 xavier에서 테스트를 진행해보았습니다.
• 기본: 8개의 cpu 코어중 하나만 3% 사용률 →
  1~3초대: 8개의 cpu 코어중 하나가 100%, 나머지가 10~20% →
  4~7초대: 8개의 cpu 코어중 하나가 100%, 하나가 50%, 나머지가 10~20% ->
  8~10초대: 8개의 cpu 코어중 하나가 100%, 하나가 50%, 나머지가 15~30%
• 이런 변화를 보입니다. 사용률이 점차 증가하는 추세가 보이는데 위의 8~10초 시간대에 사용량이 증가하는데 이 시간대가 위의 추론시간이 감소하는 구간과 일치합니다. 1~4초 사이에는 꾸준히 증가하다가 이후~7초까지는 사용량이 일정한데 8초대가 되면 더 증가하는 추세였습니다. 이 원인을 파악해야 할 것 같습니다.

[kmu-leeky]

하드웨어 메트릭에 힌트가 조금 더 있는듯 하네.
모든 자원을 사용하지 않다가, 서서히 늘려간다는 생각이 드네.
아마도 장치에서 파워등의 이유로 max 성능을 바로 내지는 않는것 같네.

아래 글들 위주로 봐보면서 동작 방법에 대해서 조금 더 이해를 해야겠다.
아래 글 말고 다른 이유가 있을수 있으니 여러 방법으로 찾아보도록 하자.

https://developer.ridgerun.com/wiki/index.php/Xavier/JetPack_5.0.2/Performance_Tuning/Maximizing_Performance

https://docs.nvidia.com/jetson/archives/l4t-archived/l4t-325/index.html#page/Tegra%20Linux%20Driver%20Package%20Development%20Guide/power_management_jetson_xavier.html

[kh3654po]

주신 링크를 보고 nvpmodel 명령어를 실행해보았습니다.
nvpmodel -p --verbose | grep POWER_MODEL을 통해 xavier의 성능을 설정할 수 있는 셋팅을 볼 수 있습니다. 여기서 ID=0가 MAXN으로 모든 cpu 및 gpu를 최대로 사용한다는 뜻입니다.

nvpmodel -m 0 명령어로 mode를 MAXN으로 설정할 수 있습니다.
nvpmodel -q 명령어로 현재 power mode 설정을 볼수 있습니다.

이렇게 설정한 후 다시 테스트 해보았지만 같은 결과를 보였습니다. 다른 방법도 찾아서 시도해보겠습니다.

[kmu-leeky]

이 현상이 우리가 최종적으로 관찰하려는 결과와 크게 상관이 없을수도 있기는 한데... 그 이유 자체가 궁금하기는 하다. 하드웨어의 특성을 파악하는 차원에서 조금 더 분석해보자.

[kh3654po]

xavier 장비내에서 실행되는 tf server에 master가 아닌 xavier에서 직접 요청을 보내봤습니다.

master에서 보냈던 경우와 마찬가지로 초당 50개의 mobilenet v1 요청을 보내보았습니다. 결과로는 기존에 요청이 쌓이고 처리시간이 증가했던 결과에 비해 네트워크 지연이 없어서 처리가 바로바로 완료된것을 볼 수 있습니다.

이 실험으로 측정한 것이 실제 요청 처리 시간이고 master에서 측정했던 시간은 실제 요청 처리시간 + 네트워크 지연시간 이라서 이러한 차이를 보이는 것 같습니다.

cpu 사용량도 확인 해본 결과 8개의 코어가 각각 15~30% 사이의 사용률로 전체적으로 증가하지는 않았습니다.

1초대 모든 요청전송 완료시간 : 1.302548885345459
1초대 완료되지 않은 요청량: 1/50
2초대 모든 요청전송 완료시간 : 1.2784349918365479
2초대 완료되지 않은 요청량: 1/100
3초대 모든 요청전송 완료시간 : 1.254539966583252
3초대 완료되지 않은 요청량: 1/150
4초대 모든 요청전송 완료시간 : 1.24127197265625
4초대 완료되지 않은 요청량: 1/200
5초대 모든 요청전송 완료시간 : 1.2176129817962646
5초대 완료되지 않은 요청량: 1/250
6초대 모든 요청전송 완료시간 : 1.1851005554199219
6초대 완료되지 않은 요청량: 1/300
7초대 모든 요청전송 완료시간 : 1.2153749465942383
7초대 완료되지 않은 요청량: 1/350
8초대 모든 요청전송 완료시간 : 1.202329158782959
8초대 완료되지 않은 요청량: 1/400
9초대 모든 요청전송 완료시간 : 1.194249153137207
9초대 완료되지 않은 요청량: 1/450
10초대 모든 요청전송 완료시간 : 1.2025771141052246
10초대 완료되지 않은 요청량: 1/500
waiting to complete...
complete!

total request num: 500
total inference time 12.306124925613403

---

inference time info (each argument is info about requests per sec)

[1] reqeust num per sec: 50
[1] avg: 0.03723716259002686
[1] min: 0.034210920333862305
[1] max: 0.041277170181274414
[1] 25%: 0.03667330741882324
[1] 50%: 0.03720545768737793
[1] 75%: 0.03807473182678223

[2] reqeust num per sec: 50
[2] avg: 0.037520675659179686
[2] min: 0.03459429740905762
[2] max: 0.04167795181274414
[2] 25%: 0.03653860092163086
[2] 50%: 0.03783273696899414
[2] 75%: 0.03835606575012207

[3] reqeust num per sec: 50
[3] avg: 0.03670249462127686
[3] min: 0.03402304649353027
[3] max: 0.04028964042663574
[3] 25%: 0.03530740737915039
[3] 50%: 0.036650657653808594
[3] 75%: 0.03804421424865723

[4] reqeust num per sec: 50
[4] avg: 0.03623586654663086
[4] min: 0.033980607986450195
[4] max: 0.04090595245361328
[4] 25%: 0.03497123718261719
[4] 50%: 0.035505056381225586
[4] 75%: 0.03776955604553223

[5] reqeust num per sec: 50
[5] avg: 0.03539103507995606
[5] min: 0.033715009689331055
[5] max: 0.03874778747558594
[5] 25%: 0.03461647033691406
[5] 50%: 0.03513956069946289
[5] 75%: 0.03595471382141113

[6] reqeust num per sec: 50
[6] avg: 0.03522792339324951
[6] min: 0.033399343490600586
[6] max: 0.0419163703918457
[6] 25%: 0.03458881378173828
[6] 50%: 0.034914493560791016
[6] 75%: 0.03540754318237305

[7] reqeust num per sec: 50
[7] avg: 0.035410194396972655
[7] min: 0.03399252891540527
[7] max: 0.04141974449157715
[7] 25%: 0.03465151786804199
[7] 50%: 0.035166025161743164
[7] 75%: 0.03565788269042969

[8] reqeust num per sec: 50
[8] avg: 0.035286669731140134
[8] min: 0.03356337547302246
[8] max: 0.038604736328125
[8] 25%: 0.03459739685058594
[8] 50%: 0.035204172134399414
[8] 75%: 0.03597283363342285

[9] reqeust num per sec: 50
[9] avg: 0.034939570426940916
[9] min: 0.03373265266418457
[9] max: 0.037538766860961914
[9] 25%: 0.03432869911193848
[9] 50%: 0.03470277786254883
[9] 75%: 0.035446882247924805

[10] reqeust num per sec: 50
[10] avg: 0.03509582042694092
[10] min: 0.033471107482910156
[10] max: 0.0367434024810791
[10] 25%: 0.0344541072845459
[10] 50%: 0.03504157066345215
[10] 75%: 0.03577685356140137

[kmu-leeky]

석현아 그렇다면

• 이전 방식 (네트워크 오버헤드 포함) 에서는 네트워크 오버헤드가 포함되는것 이 왜 후반부에 max 시간을 감소 시켰는지에 대한 분석
• 50개의 요청이 아닌 더 많은 요청을 보내서 xavier 를 saturate 시켜보기
• xavier 가 아닌 다른 기기에서 실험을 해서 요청이 쌓이는지 확인해보기

위 경우 정도를 확인 혹은 분석 해 볼만 해 보인다.

[kh3654po]

xavier 장비 내에서 inception v3 모델에 대해 추론을 실행 해 보았습니다.
아래는 초당 inception v3 요청을 100개 보냈을 때의 결과입니다.
n초대 완료되지 않은 요청량을 보시면 여러 숫자가 있는데
각각의 숫자에 대한 의미는 다음과 같습니다.

• (처리하지못한 요청량의 총합)/(요청량 총합)
• (n-1초대까지 처리완료된 요청량)/(n-1초대까지 보낸 요청량)(n-1초대까지 완료되지 않은 요청량)
• (n초대 처리하지 못한 요청량)/(n초대 요청량)

결과를 보시면 이전과 마찬가지로 9~10초에 평균 요청처리시간이 감소함을 볼 수 있습니다.
완료되지 않은 요청량이 꾸준히 증가하는 한편 9초대와 10대 처리하지 못한 요청량이 감소하는 것을 볼 수 있습니다.
이 결과를 보면 9~10초대에 처리시간이 감소하는 이유가 이전의 보낸 요청보다 9~10초대 보낸 요청이 비교적 빠르게 처리가 완료되어 감소한것으로 보입니다.

• 초당 100개 요청
  1초대 모든 요청전송 완료시간 : 2.1562352180480957
  1초대 완료되지 않은 요청량: 43/100 0/0(0) 43/100
  1초대 처리량: 57
  2초대 모든 요청전송 완료시간 : 2.6005916595458984
  2초대 완료되지 않은 요청량: 57/200 98/100(2) 55/100
  2초대 처리량: 86
  3초대 모든 요청전송 완료시간 : 2.660259485244751
  3초대 완료되지 않은 요청량: 85/300 190/200(10) 75/100
  3초대 처리량: 72
  4초대 모든 요청전송 완료시간 : 2.7707555294036865
  4초대 완료되지 않은 요청량: 107/400 278/300(22) 85/100
  4초대 처리량: 78
  5초대 모든 요청전송 완료시간 : 3.1997997760772705
  5초대 완료되지 않은 요청량: 103/500 377/400(23) 80/100
  5초대 처리량: 104
  6초대 모든 요청전송 완료시간 : 3.0378382205963135
  6초대 완료되지 않은 요청량: 106/600 474/500(26) 80/100
  6초대 처리량: 97
  7초대 모든 요청전송 완료시간 : 2.841705560684204
  7초대 완료되지 않은 요청량: 110/700 573/600(27) 83/100
  7초대 처리량: 96
  8초대 모든 요청전송 완료시간 : 3.039454221725464
  8초대 완료되지 않은 요청량: 113/800 661/700(39) 74/100
  8초대 처리량: 97
  9초대 모든 요청전송 완료시간 : 3.2000627517700195
  9초대 완료되지 않은 요청량: 118/900 749/800(51) 67/100
  9초대 처리량: 95
  10초대 모든 요청전송 완료시간 : 2.977865219116211
  10초대 완료되지 않은 요청량: 119/1000 847/900(53) 66/100
  10초대 처리량: 99
  waiting to complete...
  complete!

  total request num: 1000
  total inference time 31.100260019302368

  ---

  inference time info (each argument is info about requests per sec)

  [1] reqeust num per sec: 100
  [1] avg: 1.0252341389656068
  [1] min: 0.15681099891662598
  [1] max: 3.426561117172241
  [1] 25%: 0.4863591194152832
  [1] 50%: 0.8179521560668945
  [1] 75%: 1.291210651397705

  [2] reqeust num per sec: 100
  [2] avg: 1.753564019203186
  [2] min: 0.2762186527252197
  [2] max: 5.2254321575164795
  [2] 25%: 0.931027889251709
  [2] 50%: 1.4321181774139404
  [2] 75%: 2.3277220726013184

  [3] reqeust num per sec: 100
  [3] avg: 2.573861994743347
  [3] min: 0.44304394721984863
  [3] max: 6.968870401382446
  [3] 25%: 1.4148976802825928
  [3] 50%: 2.522016763687134
  [3] 75%: 3.4264447689056396

  [4] reqeust num per sec: 100
  [4] avg: 3.1746276092529295
  [4] min: 0.49127745628356934
  [4] max: 8.45469617843628
  [4] 25%: 1.737839937210083
  [4] 50%: 3.158302068710327
  [4] 75%: 4.355912685394287

  [5] reqeust num per sec: 100
  [5] avg: 3.3617399311065674
  [5] min: 0.7000854015350342
  [5] max: 9.040663719177246
  [5] 25%: 2.0209970474243164
  [5] 50%: 3.212369680404663
  [5] 75%: 4.441608428955078

  [6] reqeust num per sec: 100
  [6] avg: 3.2744247198104857
  [6] min: 0.422757625579834
  [6] max: 14.119304418563843
  [6] 25%: 1.9514894485473633
  [6] 50%: 2.771293878555298
  [6] 75%: 4.226333141326904

  [7] reqeust num per sec: 100
  [7] avg: 3.781122262477875
  [7] min: 0.3690676689147949
  [7] max: 11.068968296051025
  [7] 25%: 1.5777318477630615
  [7] 50%: 3.5043561458587646
  [7] 75%: 5.203884601593018

  [8] reqeust num per sec: 100
  [8] avg: 4.116867516040802
  [8] min: 0.4384291172027588
  [8] max: 10.824107646942139
  [8] 25%: 1.0986816883087158
  [8] 50%: 4.2473695278167725
  [8] 75%: 6.277559041976929

  [9] reqeust num per sec: 100
  [9] avg: 2.9894442558288574
  [9] min: 0.25463390350341797
  [9] max: 7.438498258590698
  [9] 25%: 0.9823367595672607
  [9] 50%: 1.8734784126281738
  [9] 75%: 5.775633096694946

  [10] reqeust num per sec: 100
  [10] avg: 1.9179635286331176
  [10] min: 0.3687605857849121
  [10] max: 4.689980506896973
  [10] 25%: 0.9706339836120605
  [10] 50%: 1.80540132522583
  [10] 75%: 2.69557523727417

[kmu-leeky]

"910초대에 처리시간이 감소하는 이유가 이전의 보낸 요청보다 910초대 보낸 요청이 비교적 빠르게 처리가 완료" 어떤 이유로 이런 현상이 가능할까?