제니퍼 닷넷 적용 사례 (2) - 웹 애플리케이션 hang의 원인을 알려주다.
지난번 글에서, 마지막에 '관리가 느슨해지는 사례'를 잠시 언급했는데요.
제니퍼 닷넷 적용 사례 (1) - DB Connection Pooling을 사용하지 않았을 때의 성능 저하를 알려주다.
; https://www.sysnet.pe.kr/2/0/1111
올해 초에 방문했던 A 고객사 또한 그와 유사한 '관리 부재'를 겪고 있었습니다. 개발은 외주 업체에 의해서 진행되었는데, 몇 년이 흐른 사이 해당 업체들이 가끔씩 바뀌기도 하는 바람에 '산출물의 안정성'에 불안감을 느끼고 있었던 것인데요. 그러던 중에 APM 툴이 도움이 될 수 있겠다 싶어 알아보았는데, 국내 제품 중에는 '제니퍼 닷넷'밖에 없어서 선택의 여지없이 연락을 하게 되었다고 합니다. ^^
A 고객사에는 설치부터 다소 특이하긴 했습니다. 원래는 '테스트 서버'에 먼저 적용하고 이상이 없다 싶으면 '실 서버'에 적용하는 순으로 진행하는데, A 고객사에서는 '실 서버'에 바로 적용을 한 것입니다. 게다가 사용자가 가장 많은 시간대에 서슴없이 ^^ 설치하였는데, 우리는 전혀 그 사실을 모르고 있었습니다.
설치를 하고, 웹 서버가 응답이 없는 상황이 되어 현재 사용자들이 전혀 사용을 못하고 있다는 말들이 들려오면서야 '실 서버'라는 사실을 알았고 곧바로 '제니퍼 닷넷'을 내리게 되었습니다. 도대체 어떤 원인으로 웹 서버가 Hang 상태에 빠지게 된 것인지 그 현상만 보고는 전혀 짐작할 수가 없었습니다.
위의 원인을 밝히기 전에, '제니퍼 닷넷'의 '서비스 덤프' 기능을 먼저 소개해 드려야 할 것 같습니다.
일반적으로, 웹 서버가 요청을(예를 들어, test.aspx) 받으면 해당 웹 페이지에 포함된 코드를 실행하게 되는데 보통 DB 연결이라든가 외부 웹 서비스 접속에 의해서 처리가 느려져 응답이 완료되지 않으면 제니퍼에서는 그 사실을 Speed meter라는 UI를 통해서 보여줍니다.
아래의 글에 제니퍼 닷넷이 동작 중인 화면을 실어놓았는데,
성능 관리 퀴즈 첫 번째 문제 (닷넷 개발자 컨퍼런스)
; https://www.sysnet.pe.kr/2/0/875
그중에서, 아래의 그림에 해당하는 부분이 바로 'Speed meter'로 '현재 처리 중인 요청' 수를 보여주는 것입니다.
즉, 위의 그림에 따르면 바로 그 화면을 보고 있는 순간에, ASP.NET 엔진이 10개의 요청을 처리 중에 있음을 알 수 있고, 막대가 '빨간색'인 것은 처리 시간이 이미 8초를 넘었다는 것을 의미하고 있습니다. 그렇다면, 도대체 10개의 aspx 요청에 대해서 어떤 코드를 실행하다가 저렇게 막히게 된 것일까요?
그 원인을 알고 싶다면, 'speed meter'의 막대 부분을 마우스로 더블 클릭하면 '현재 처리 중인 요청'에 대한 목록을 확인할 수 있고,
8초 이상 걸리고 있음을 알려주는 빨간색 링크를 클릭하면 아래와 같이 해당 요청을 처리하고 있는 스레드의 'Call Stack'을 확인할 수 있습니다.
이를 통해서, 어떤 메서드를 수행 중에 처리가 지연되고 있는지 알 수 있고 대부분의 경우에 'DB Lock'으로 인해 처리가 지연되어 해당 SQL 쿼리를 튜닝하는 것으로 문제를 해결할 수 있습니다.
그런데, 위에서 보여준 시나리오는 '개발자가 아닌 서버 관리자' 입장에서는 어쩌면 '암호'를 보는 것과 같은 기분일 수 있습니다. 중요한 것은 위의 장애가 발생한 시점에 '처리가 지연되고 있는 요청들의 콜스택'을 개발자에게 온전하게 전달해야 한다는 것인데요. 제니퍼는 이런 시나리오를 고려해서 '서비스 덤프'라는 기능을 제공하고 있습니다. 그래서 서버 관리자가 이런 장애를 목격하면, 곧바로 '제니퍼 콘솔' 화면의 '장애진단' / '서비스 덤프' 기능으로 들어가서 '덤프' 버튼을 눌러 '현재 처리 중인 요청들의 목록 및 그 정보'를 파일로 남길 수 있고, 일단 서버의 장애 조치를 취한 다음 그 파일을 개발팀에게 넘겨주어 문제의 원인 파악을 도울 수 있습니다. 아래는 그렇게 해서 남긴 '서비스 덤프'의 예를 보여주고 있습니다.
제니퍼의 '서비스 덤프'기능이 'A 고객사'의 웹 서버가 오동작하는 원인을 밝혀주는 데 어떻게 기여할 수 있었을까요?
위에서 설명한 '서비스 덤프'는 사용자가 직접 수행해서 남기는 경우를 설명하고 있지만, '제니퍼 닷넷'은 부가적으로 설정 파일에 정의된 '임계치(기본값: 100)'에 의해서 자동으로 남겨지는 기능도 구현하고 있습니다. 마침, A 고객사에서 제니퍼 닷넷을 올렸을 때에도 '현재 처리 중인 요청'의 수가 임계치에 다다르게 되었고 자동으로 서비스 덤프가 남겨지게 되었던 것입니다.
그렇게 남겨진 서비스 덤프의 개별 스레드에 대한 콜스택을 검토해보니, .NET의 HttpWebRequest 타입을 통해 외부 파일을 요청하는 메서드 - GetRequestStream에서 전체적으로 lock이 걸린 것을 확인할 수 있었습니다. 재미있는 점은, 해당 Web 요청의 URL이 "http://
localhost/.../config.xml"이었다는 것! (사실, 공통 모듈의 static 메서드에서 Monitor.Lock으로 config.xml을 반환하는 식의 약간 복잡한 내부 규칙이 있었긴 합니다.)
아하~~~ 대략적인 원인이 나왔습니다.
'제니퍼 닷넷'을 설치해서 'iisreset'을 수행한 시간이 마침 사용자가 많이 몰리는 시간이어서 웹 서버는 순식간에 120 여개의 요청을 받아들이게 되었고, 해당 aspx.cs 내부에서 사용중인 공통 모듈은 초기화를 위해 '같은 웹 애플리케이션 경로에 저장된 설정 파일(config.xml)'을 HttpWebRequest 개체를 이용해서 받아오는 동작을 완료하지 못하고 있었던 것입니다. 즉, 문제는 120 여개의 요청으로 인해 웹 서버는 이미 스레드 풀에 할당된 스레드 갯수를 소진한 상태이고 그중에서 어느 하나라도 스레드가 완료되어야 "http://localhost/.../config.xml"에 대한 요청을 다시 받아들일 수가 있는데 그렇지 못해서 지속적인 lock 상태로 빠져들게 된 것이었습니다.
원인 파악이 된 후, A 고객사의 외주 개발팀의 PL에게 혹시 전에도 이런 현상을 겪은 적이 없었는지 물어보았습니다. 안 그래도 가끔씩 서비스를 내렸다 올릴 때 그런 현상이 발생해서 그럴 때마다 다시 서비스를 내렸다 올리는 식으로 해결을 했다면서 그동안 그 원인을 알 수 없었다고 우리에게 말해 주었습니다. (왜 하필 내렸다 올렸을 때 이런 현상이 두드러지게 나타났을까요? 퀴즈로 남겨두겠습니다. ^^)
^^ 만족스러운 답변에 갑자기 의기양양해지면서 친절하게 그 원인에 대한 해결책을 설명해 드렸지요. config.xml 파일이 있는 폴더만 별도의 ThreadPool을 가지도록 또 다른 웹 애플리케이션으로 승격해 주거나, 아니면 HttpWebRequest가 아닌 직접적인 파일 접근으로 우회하면 해결될 것이라고 말씀드렸습니다. (그 당시에는, 코드의 수정을 최소화하기 위해 웹 애플리케이션으로 승격하는 방법이 선택되었습니다.)
문제 해결 후에, 정상적으로 다시 '제니퍼 닷넷'이 설치되어 동작하게 되었고 설치 시점부터 효과를 눈으로 확인한 A 고객사는 '제니퍼 닷넷'을 전적으로 신뢰하게 되어 결국 도입까지 자연스럽게 마무리가 되었습니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]