서버 배포시에 항상 알림이 왔던 상황을 풀어 해쳤던 이슈에 대해서 공유를 드리려고합니다.

저희 서버 배포때 일어났던 현상들인데요.

어느날 부터인가, server를 deploy 하게되면 request thread들이 응답을 굉장히 늦게 주는 현상 들이 발생되었습니다 😂

네이버 오픈소스 APM 툴로 Pinpoint를 사용하는데요. 엄청나게 여러개의 토네이도(👀) 들이 발생되는 현상들이 보여집니다. 사용자의 request를 빠르게 응답하지못하여서 생기는 현상이었죠.

처음에는 L4 binding할때만 문제가 생겨서 별문제 없겠지. 라고 생각하였지만, 점점 매 배포때마다 저 토네이도(?)가 굉장히 거슬렸습니다.

도대체 배포때마다 생기는 저 문제가 무엇일까 고민하고 확인을 해보았습니다.
먼저 어떠한 문제가 생겼는지 어떻게 이문제를 풀어나가야 될지 고민을 한 이야기들을 공유드리겠습니다.

1. CPU사용

가장 먼저 cpu사용률 적정치이상 사용하게 되면 문자가 오는 알람 시스템을 사용하고 있었는데요. 배포 당시에 서버마다 80~90퍼 이상의 cpu사용률에 대한 문자 알람이 지속적으로 왓었습니다. 그래서 먼저 배포당시에 java의 어떤 thread가 가장 많이 cpu를 사용하는지 확인을 해보았습니다.

ps -mo pid,lwp,stime,time,%cpu -C java

위 명령어를 사용하게되면 java process의 thread pid lwp stime cpu 사용률을 알수있게 됩니다.

위와 같이 PID에 해당되는 LWP가 나오게되는데요.
LWP는 thread의 10진수 nid 값이 되게 됩니다.
허나, 저 thread가 어떤 thread인지는 ps 명령어만을 이용해서는 확인이 불가능합니다. 결국 jstack이라는 명령어를 이용해서 java process에 대한 정보 dump를 뜰 수가 있습니다.

이젠 jstack을 이용해서 어떤 thread가 cpu를 많이 잡아 먹는지 확인을 해보면 됩니다.

• Thread name
• Thread Number
• nid(Native Id) - OS에서 제공하는 스레드의 고유 ID

nid값을 이용해서 어떤값이 병목이 되는 thread인지 확인을 해볼수있는데요.

ps로 뽑아낸 cpu사용률이 가장 큰 LWP값을 16진수로 변환하게되면, jstack에서 나오는 nid 값으로 어떤 thread 정보인지 알 수 있습니다.

저희가 배포시에 가장 많은 사용률을 잡아먹는 thread는 C2 Compiler Thread로 판명되었습니다.

그렇담, C2 Compiler Thread가 도대체 어떤 Thread이길래 가장 cpu를 많이 차지 하고 있는가?

http://openjdk.java.net/groups/hotspot/docs/HotSpotGlossary.html

이렇다고 나와있네요...

여러가지 글들을 참고해보니, 초기 load시에 최적화를 많이 하는작업이라 초기 class load시에 많은 cpu자원을 사용 할 수 있다고 하네요.

즉 C2 Compiler의 load start up시에 많이 자원을 소비했다고 판단이 되었습니다.

그러면 이제는 좀 더 자세하게 어떤 request가 cpu 자원을 많이 소비했을까에 대해서 pinpoint로 확인을 해보았습니다.

2. JSP Compile

첫번째, jsp를 return하는 thread들이 10000ms 이상의 response응답시간이 걸리게되었습니다.

그런데 초기로드시에만? 느리고 그이후로 빠른응답을 주는게 참 이상한데 말이죠?

jsp life cycle을 보게되면 이 현상은 당연히 일어날수 있다고 볼수있습니다.

• Compilation
• Initialization
• Execution
• Cleanup

네가지로 이루어 져있는데요.

먼저 Compilation은 Request가 해당 jsp첫 요청을 하게되면, JSP 엔진은 먼저 페이지를 컴파일해야하는지 여부를 확인합니다. JSP가 마지막으로 컴파일 된 이후 수정 된 경우 JSP 엔진이 페이지를 컴파일합니다.

• JSP 구문 분석
• JSP를 서블릿으로 전환
• 서블릿을 컴파일

즉 해당 controller로 첫요청이 들어와야 jsp 엔진은 그때 lazy initilzation을 한다는 이야기입니다.

첫 요청을 사용자의 주도로 이루어지면, request가 jsp initialization을 대기를 해야되고 그만큼의 시간이 response time을 늘리게끔 만드는 요인이 될 수 있는 것 입니다.

위 상황을 처리하기위해 원시적인(?) 방법을 이용하여 deploy시, l4 binding 하기전에 jsp를 return하는 controller를 전부 curl로 call 하여 preloading을 진행해주었습니다.

그랬더니 결과가..

성공적으로 jsp response time이 길었던 request들은 전부 해소 되었습니다. 큰 성과를 이루었다고 생각 하였지만, 여전히 CPU사용률은 70퍼 정도의 다다를 정도로 많이 사용되고 있었죠(😭)

cpu사용률은 왜 줄이지 못할까.. 라는 의심을 계속 고민을 하고 있습니다.. 좋은 아이디어가 떠오른다면 추후 글로 한번 옮겨 볼 예정입니다 ㅎㅎㅎ

추후 해결하게 된다면 다시 공유드리겠습니다 😃