Open kh3654po opened 1 year ago
현재 cuda code도 작성하여 실행해보는데 cuda 코드가 제대로 작동하지 않고 있습니다. 제 코드가 문제인지 확인하고자 튜토리얼 코드를 실행해봤을때도 작동이 안됩니다. 튜토리얼 코드는 다음과 같습니다.
#include <stdio.h>
void CPUFunction()
{
printf("This function is defined to run on the CPU.\n");
}
__global__ void GPUFunction()
{
printf("This function is defined to run on the GPU.\n");
}
int main()
{
CPUFunction();
GPUFunction<<<1, 1>>>();
cudaDeviceSynchronize();
}
global 이 있는 함수가 gpu에서 실행되는 함수입니다. main에서 cpu함수와 gpu함수를 모두 호출합니다. gpu함수를 호출할때 cpu함수와 다르게 GPUFunction<<<1, 1>>>() 형식으로 호출합니다. cpu연산과 gpu연산은 동시에 실행 될 수 있기때문에 gpu연산이 다 끝나지 않더라도 main함수가 종료될 수 있습니다. cudaDeviceSynchronize() 이 함수는 모든 연산이 종료될 때까지 기다리는 함수입니다.
즉 출력 결과로는 다음으로 예상 되지만 실제로는 GPU 관련 결과는 나오지 않습니다.
This function is defined to run on the CPU.
This function is defined to run on the GPU.
제가 작성한 코드는 gpu에서 행렬곱하도록 하는 코드인데 a, b행렬연산을 c에 저장하여 결과를 출력하는 코드입니다. 결과로 계산이 안된 초기값 0이 들어있어 gpu연산이 안됐습니다. 튜토리얼 코드와 마찬가지로 gpu연산이 안돼서 이부분을 해결해보겠습니다. 코드는 작성이 되어서 이제 gpu연산문제만 해결되면 결과를 확인해 볼 수 있을거 같습니다.
석현아 처음 gpu 프로그래밍을 하는듯 해서 쉽지 않은가보다. 일반적인 gpu 라면 조금 더 참조할 자료가 많을텐데 엣지 기반 gpu 장비여서 참조할 자료가 부족할수 있겠다. 세부적인 동작 방법 확인을 위해서는 꼭 필요한 절차일듯 하니, 여러 자료 참조하면서 진행해보자. 참조하는 튜토리얼 혹은 기본적인 정보 사이트 혹은 자료가 있으면 공유해줘도 좋고. 책 혹은 외부 강의 등이 도움이 될것 같다면 알려주고.
xavier에서 c와 go 두개의 언어로 gpu 행렬연산을 하는 코드를 작성해 테스트 해보았습니다. 600x600 행렬 두개를 gpu에서 행렬곱을 하고 이 연산을 초당 100개 10초동안 하도록 하였습니다. 결과 c와 go 모두 한 쓰레드당 처리시간이 4\~5ms였고 완료순서는 생성된 순서와 같았습니다. gpu활용률은 15\~30%였습니다.
출력 결과의 일부입니다. 두개의 결과가 비슷한것을 볼 수 있습니다. 이러한 결과를 봤을때 이전문제가 python의 GIL이 아닌가 의심이 되는데 현재 구동중인 tfserver에 go언어로 병렬 요청을 보내고 처리시간을 측정해보겠습니다. 만약 결과가 파이썬과 다르다면 언어의 문제로 이전의 이슈가 나온것으로 의심할 수 있을거 같습니다.
// c
Thread 630, matrix_result[0]=1543994, start time: 6.4306, end time: 6.4360, processing time: 0.0054 seconds
Thread 631, matrix_result[0]=1543994, start time: 6.4408, end time: 6.4463, processing time: 0.0056 seconds
Thread 632, matrix_result[0]=1543994, start time: 6.4509, end time: 6.4564, processing time: 0.0055 seconds
Thread 633, matrix_result[0]=1543994, start time: 6.4612, end time: 6.4667, processing time: 0.0055 seconds
Thread 634, matrix_result[0]=1543994, start time: 6.4714, end time: 6.4769, processing time: 0.0055 seconds
Thread 635, matrix_result[0]=1543994, start time: 6.4817, end time: 6.4873, processing time: 0.0056 seconds
Thread 636, matrix_result[0]=1543994, start time: 6.4918, end time: 6.4974, processing time: 0.0056 seconds
Thread 637, matrix_result[0]=1543994, start time: 6.5021, end time: 6.5076, processing time: 0.0055 seconds
Thread 638, matrix_result[0]=1543994, start time: 6.5122, end time: 6.5178, processing time: 0.0056 seconds
Thread 639, matrix_result[0]=1543994, start time: 6.5225, end time: 6.5280, processing time: 0.0054 seconds
Thread 640, matrix_result[0]=1543994, start time: 6.5327, end time: 6.5383, processing time: 0.0055 seconds
Thread 641, matrix_result[0]=1543994, start time: 6.5430, end time: 6.5485, processing time: 0.0055 seconds
Thread 642, matrix_result[0]=1543994, start time: 6.5533, end time: 6.5584, processing time: 0.0052 seconds
Thread 643, matrix_result[0]=1543994, start time: 6.5634, end time: 6.5687, processing time: 0.0053 seconds
Thread 644, matrix_result[0]=1543994, start time: 6.5736, end time: 6.5790, processing time: 0.0054 seconds
Thread 645, matrix_result[0]=1543994, start time: 6.5839, end time: 6.5895, processing time: 0.0056 seconds
Thread 646, matrix_result[0]=1543994, start time: 6.5940, end time: 6.5996, processing time: 0.0055 seconds
Thread 647, matrix_result[0]=1543994, start time: 6.6042, end time: 6.6099, processing time: 0.0057 seconds
Thread 648, matrix_result[0]=1543994, start time: 6.6145, end time: 6.6199, processing time: 0.0054 seconds
Thread 649, matrix_result[0]=1543994, start time: 6.6245, end time: 6.6301, processing time: 0.0056 seconds
Thread 650, matrix_result[0]=1543994, start time: 6.6349, end time: 6.6404, processing time: 0.0055 seconds
[630] c[0]=1427871, start time: 6.383905755s, end time: 6.387874352s, processing time: 3.968597ms
[631] c[0]=1427871, start time: 6.394034074s, end time: 6.397877128s, processing time: 3.843054ms
[632] c[0]=1427871, start time: 6.40417017s, end time: 6.407987847s, processing time: 3.817677ms
[633] c[0]=1427871, start time: 6.414301242s, end time: 6.418191787s, processing time: 3.890545ms
[634] c[0]=1427871, start time: 6.424412793s, end time: 6.42820778s, processing time: 3.794987ms
[635] c[0]=1427871, start time: 6.43454108s, end time: 6.438337092s, processing time: 3.796012ms
[636] c[0]=1427871, start time: 6.444662359s, end time: 6.448867385s, processing time: 4.205026ms
[637] c[0]=1427871, start time: 6.455280817s, end time: 6.459366284s, processing time: 4.085467ms
[638] c[0]=1427871, start time: 6.4654052s, end time: 6.469486411s, processing time: 4.081211ms
[639] c[0]=1427871, start time: 6.475526095s, end time: 6.479729489s, processing time: 4.203394ms
[640] c[0]=1427871, start time: 6.485671696s, end time: 6.48973953s, processing time: 4.067834ms
[641] c[0]=1427871, start time: 6.495800079s, end time: 6.499836936s, processing time: 4.036857ms
[642] c[0]=1427871, start time: 6.505910286s, end time: 6.510167731s, processing time: 4.257445ms
[643] c[0]=1427871, start time: 6.516072431s, end time: 6.520309715s, processing time: 4.237284ms
[644] c[0]=1427871, start time: 6.526156141s, end time: 6.530152483s, processing time: 3.996342ms
[645] c[0]=1427871, start time: 6.536269067s, end time: 6.540364967s, processing time: 4.0959ms
[646] c[0]=1427871, start time: 6.546399019s, end time: 6.550323773s, processing time: 3.924754ms
[647] c[0]=1427871, start time: 6.556537771s, end time: 6.560449725s, processing time: 3.911954ms
[648] c[0]=1427871, start time: 6.566651082s, end time: 6.57056214s, processing time: 3.911058ms
[649] c[0]=1427871, start time: 6.576782153s, end time: 6.580664442s, processing time: 3.882289ms
[650] c[0]=1427871, start time: 6.586879847s, end time: 6.591223184s, processing time: 4.343337ms
오케이. 석현아. xavier 에서 프로그래밍을 성공한것 같구나. 전에 작업을 할때 이슈가 있었을것 같은데, 어떻게 해결했는지 공유를 해줄래? 코드도 일찍 같이 리뷰해보는것도 좋겠다. gpu 가 사용된다는건 어떻게 확인을 했어?
석현이 지금 생각은 요청을 python 에서 보내면서 문제가 발생한것 같다는 거지? 그렇다면 다른 언어로 진행해보는것도 괜찮겠다.
cuda에서 gpu연산을 하는 함수를 선언할 때 globle을 붙여주는데 이 함수를 호출 할 때는 dim3타입인 grid와 block을 같이 전달 해야 합니다. 예를 들어 function<<grid, block>>()입니다. thread가 모여 block이 되고 block이 모여 grid가 되는데 제가 전에 사용했던 코드에서는 block의 크기를 64x64로 지정하였습니다. 공유해주신 샘플코드를 보니 거기서는 16 또는 32로 되어있어 block의 크기를 32x32로 바꾸니 되었습니다. 코드는 정리해서 PR에 올리도록 하겠습니다. gpu는 jtop과 tegrastats 명령어로 확인했습니다.
오케이. jetson 계열의 장비가 스펙이 조금은 떨어져서 작은 사이즈를 해줬어야 했나보다. jtop 으로 확인했다면 잘 확인은 되었을것 같고, 석현이가 의심하고 있는 python 에서 요청 보내는 부분을 수정해서 실험해보자.
go언어로 master에서 xavier로 요청을 보내 결과를 확인해보았습니다. 0.1초마다 inception v3 요청을 보내고 총 보낸 요청은 100개입니다. 즉 초당 10개씩 10초동안 100개를 요청해보았습니다. 출력 결과는 각 요청 순서, 시작시간, 종료시간, 처리시간입니다. 시간은 마스터에서 측정한 것으로 실제 요청처리 + 네트워크지연시간을 포함합니다. 다음은 결과의 일부입니다.
[74] start time: 7.44002867s, end time: 13.692613334s, processing time: 6.252584664s
[76] start time: 7.641348519s, end time: 13.772979421s, processing time: 6.131630902s
[77] start time: 7.741522172s, end time: 13.850484832s, processing time: 6.10896266s
[86] start time: 8.64517501s, end time: 13.927730622s, processing time: 5.282555612s
[87] start time: 8.745892204s, end time: 14.006506624s, processing time: 5.26061442s
[93] start time: 9.349858607s, end time: 14.083513558s, processing time: 4.733654951s
[53] start time: 5.328576851s, end time: 14.162575271s, processing time: 8.83399842s
[97] start time: 9.752031608s, end time: 14.240791005s, processing time: 4.488759397s
[98] start time: 9.852818655s, end time: 14.318736751s, processing time: 4.465918096s
[99] start time: 9.953703613s, end time: 14.39690861s, processing time: 4.443204997s
[69] start time: 6.937680241s, end time: 14.4735546s, processing time: 7.535874359s
53번과 69번을 보시면 앞뒤 요청들보다 3\~5초 먼저 보내졌지만 완료는 더 늦게 되었습니다. 여러번 다시 측정해보아도 비슷한 양상을 보입니다.
여기서 다음으로 의심되는 것이 tf server의 스케줄링입니다. server의 log를 찍어보는 방벙 등 확인할 수 있는 방법을 찾아서 시도해보겠습니다.
오케이. 석현아 좋은 발견이다. tfserving 의 스케줄러도 의심이 되기는 한다. tfserving 서버의 코드가 공개되어 있고, 엣지 자비에서 구동할 경우에는 다양한 디버깅 메시지 확인도 가능할테니 조금 더 깊이 있게 분석해보자.
환경변수 TF_CPP_VMODULE=http_server=1 를 추가하면 아래와 같이 들어오는 요청에 대한 로그는 찍혔지만 몇번째 요청인지와 처리완료 됐다는 로그는 찍히지 않았습니다. 이에 코드를 분석하고 있는데 생각보다 파악이 어려워 시간이 더 걸릴거 같습니다.
오케이. 디버깅 플래그 설정하면서 메시지 확인하면서 진행하는게 맞아. 지금 보면 "TF_CPP_VMODULE=http_server=1" 이걸 추가했는데,
https://github.com/tensorflow/serving/issues/285 여기에 보면 You can use command: "export TF_CPP_MIN_VLOG_LEVEL=3", it works to me.
이런 이야기도 있는데 다른 옵션도 한번 시도를 해봤어?
넵 TF_CPP_MIN_VLOG_LEVEL도 테스트해봤습니다. 아래가 3을으로 설정했을때인데 실시간으로 매초 수십라인씩 로그가 찍혔습니다. 요청을 보내고 로그를 기록하여 확인해보니 TF_CPP_VMODULE=http_server=1 와 다르게 요청이 들어오고 처리하는 과정을 파악하기 힘들었습니다. 로그를 다시한번 분석해보겠습니다.
TF_CPP_MIN_VLOG_LEVEL와 같이 실시간으로 계속해서 로그가 찍히는 방법으로는 파악이 어려울것같습니다. 다른방법을 찾아보겠습니다.
석현아. 1 부터 4라는게 디버깅 레벨을 이야기 하는 것이거든. 3이 너무 자주 찍힌다면 다른 숫자를 한번 시도해 봐. 조금 덜 찍히는 옵션이 있을거야. 내 생각에는 저런 로그들이 현재 상황에서는 진행 상황을 모니터링 할 수 있는 방법일것 같거든. 다른 방법은 요청을 보낼때 요청 보내는 인덱스 번호 (1부터 순차적으로 증가) 를 함께 보내고 그걸 출력을 해보면 좋을텐데, 그러러면 tf serving 의 코드 자체를 수정 및 새롭게 빌드해야 해서 일이 조금 더 커질것 같기는 하다. 필요하면 그 방향이 더 나을수도 있고.
[0]초대 평균처리시간: 7.43567704s
[1]초대 평균처리시간: 15.083398122s
[2]초대 평균처리시간: 19.167541454s
[3]초대 평균처리시간: 19.546202811s
[4]초대 평균처리시간: 21.079104629s
[5]초대 평균처리시간: 23.834932108s
[6]초대 평균처리시간: 22.483112805s
[7]초대 평균처리시간: 24.614571869s
[8]초대 평균처리시간: 24.510732074s
[9]초대 평균처리시간: 24.387041974s
tfserving 의 로그를 활용한 분석이 쉽지는 않은 모양이네. Go 를 활용해서 요청을 보내서 확인을 한것 같네. 그런데 전에 코멘트를 보면 요청을 Go 로 보내더라도 요청을 보낸 순서대로 응답이 도착하지 않는 문제가 있지 않았었나? https://github.com/ddps-lab/tfserving-inference/issues/46#issuecomment-1651588129
우리 연구의 핵심적인 부분이 아닐 수 있지만, tfserving 의 문제인지 xavier 장치의 문제인지 요청을 보내는 순서대로 처리가 되지 않는 문제는 있는듯 해보이는데 그 문제를 조금 더 깊이 있게 봐보고 싶기는 해.
xavier의 스케줄링 정책이 엣지가 아닌 다른 컴퓨터의 스케줄링 정책과 다른지 확인하기 위해 aws의 t3.xlarge에서 tf serving을 테스트 해보았습니다. gpu를 사용하지 않고 cpu를 사용합니다. 10초 동안 매초 5개의 inception v3 요청을 전송(하드웨어 고려)하였습니다. 결과는 일부분만 가져왔습니다.
[1] start time: 201.106497ms, end time: 19.476783113s, processing time: 19.275676616s
[25] start time: 5.015404523s, end time: 38.204074623s, processing time: 33.1886701s
[19] start time: 3.811825886s, end time: 42.827775915s, processing time: 39.015950029s
[5] start time: 1.003237237s, end time: 45.946513199s, processing time: 44.943275962s
[8] start time: 1.604990489s, end time: 45.99261834s, processing time: 44.387627851s
[48] start time: 9.628865257s, end time: 47.55593123s, processing time: 37.927065973s
[36] start time: 7.222925986s, end time: 47.890168115s, processing time: 40.667242129s
[22] start time: 4.413964941s, end time: 48.282780296s, processing time: 43.868815355s
[7] start time: 1.404498576s, end time: 51.129027326s, processing time: 49.72452875s
[30] start time: 6.018726967s, end time: 53.336901115s, processing time: 47.318174148s
[4] start time: 802.120661ms, end time: 54.436274279s, processing time: 53.634153618s
[23] start time: 4.614749315s, end time: 56.859770042s, processing time: 52.245020727s
[40] start time: 8.024590263s, end time: 57.214469318s, processing time: 49.189879055s
...
[0]초대 평균처리시간: 43.76330964s [1]초대 평균처리시간: 53.348497852s [2]초대 평균처리시간: 1m1.885414843s [3]초대 평균처리시간: 55.353841155s [4]초대 평균처리시간: 55.641120018s [5]초대 평균처리시간: 55.926897667s [6]초대 평균처리시간: 56.40145111s [7]초대 평균처리시간: 55.957669266s [8]초대 평균처리시간: 55.007296416s [9]초대 평균처리시간: 52.465659847s
마찬가지로 완료순서가 다른것을 확인했습니다. tf serving 코드를 보면서 요청처리를 어떻게 하는지 확인해보겠습니다.
xavier 에서 발견된 문제가 cpu 에서도 관측이 되는 구나. 빠르게 잘 진행을 했다. 그런데 요청하나의 시간이 너무 오래 걸리는 구나. 하나의 요청에 대한 처리 시간이 너무 오래 걸려서 이대로 결과를 해석해도 될런지 약간은 염려가 되기는 해. 몇가지 확인했으면 하는 점은
tf servinf 옵션중에 tensorflow_intra_op_parallelism및 tensorflow_inter_op_parallelism가 있습니다. 해당 옵션에 대한 설명은 https://github.com/IntelAI/models/blob/master/docs/general/tensorflow_serving/GeneralBestPractices.md#tensorflow-serving-configuration-settings에 있고 아래는 해당링크에서 가져온 설명입니다.
tensorflow_intra_op_parallelism는 코어수와 같게 4로 설정하고 tensorflow_inter_op_parallelism는 설명에서 말한대로 2로 설정하였습니다. 이렇게 실험을 진행하여도 같은 결과가 나왔습니다. 요청의 수를 늘려 10초동안 매초 10개의 요청을 보내봤는데 이 또한 마찬가지로 10%사용량을 보이다가 요청을 보낸 서버에서 첫 response를 받고 잠시뒤에 서서이 증가하여 30\~50% 사용했습니다.
혹시 docker에서 자원량을 제한하고 있나 확인해보니 docker는 제한을 명시하지않으면 기본적으로 모든자원을 사용하려고 한다고 합니다. https://docs.docker.com/config/containers/resource_constraints/ 에서 첫출에 "By default, a container has no resource constraints and can use as much of a given resource as the host’s kernel scheduler allows."라고 적혀있습니다. 다른 이유가 있나 더 찾아보겠습니다.
석현아. cpu 에서 확실히 정상동작하는것 같지는 않다. 여러 방법으로 확인을 해봤지만 아직은 원인은 없는듯 하고.
우리의 핵심 목표가 xavier+tfserving 에서의 문제 해결인 만큼 CPU 환경에서 문제 해결에 얼마나 더 시간을 쏟을지는 석현이가 잘 결정하면 좋겠다. CPU 상에서도 차례가 지켜지지 않았음이 보였던 만큼 (실험 결과를 100% 신뢰할수 는 없지만), TFserving 의 시스템을 분석해서 요청 처리 순서가 지켜지지 않을 가능성이 있는 부분을 찾는것도 좋은 방향인것 같은 생각이 든다.
어떤 방향으로 시간을 더 사용할건지 (CPU 환경에서 디버깅 혹은 TFserving 코드 분석), 석현이가 정해서 코멘트 달아주면 좋겠다.
행렬곱연산을 할 때 cpu가 아닌 gpu에서 사용하도록한다.
병렬로 실행할 때 각 실행번호, 실행시작 시간, 종료 시간을 출력해 스케줄링이 어떻게 일어나고 있는지 확인한다.
현재 상황 c언어와 go언어 둘다 cuda를 이용하면 gpu를 사용하는게 가능합니다. go 문법은 익혔으나 cuda를 사용하는데에는 좀 더 시간이 필요할거 같습니다.