제니퍼 닷넷 적용 사례 (3) - '닷넷'이 문제일까? '닷넷 개발자'가 문제일까?
아래의 글을 읽어보면,
닷넷 가비지 컬렉션 다시 보기 - Part IV
; http://www.simpleisbest.net/post/2011/04/18/When-GC-Occurs.aspx
재미있는 사례가 하나 나옵니다.
필자가 몇 년 전 모 보험 회사의 성능 튜닝에 들어갔을 때 보았던 코드는 수 백 개의 테이블을 가진 Typed DataSet이 문제의 원인이었다. 이 데이터 셋은 단순히 new 하는 것만으로도 64MB 정도의 메모리를 쳐먹었으며 이 메모리를 할당하는 동안 몇 차례의 가비지 컬렉션이 발생할 정도였다. 그리고 더 웃긴 것은, 이 뷩신 같은 데이터 셋을 테이블 1-2개 조회하는데 잠깐 사용하고 버려버리는 코드들이 발견 되었다. 이로 인해 0, 1, 2세대 가비지 컬렉션이 미친 듯이 발생했고 CPU는 가비지 컬렉션만 수행하다 볼일을 다 보고 웹 사이트는 무지하게 느려진 것이다. (이런 미친 코드를 작성한 SI 업체는 어디론가 도망가 버렸고 그 보험 회사는 닷넷 욕을 엄청 해 댔으며, 6개월 후 시스템 개편 때 미련 없이 이 어플리케이션을 자바로 갈아치워 버렸다!)
닷넷하면서... 저렇게 자바로 넘어갔다는 사연을 심심치 않게 들어볼 수 있는데, 그저 안타까울 뿐입니다.
'제니퍼 닷넷' 성능 모니터링 도구를 적용하는 사이트를 보면서, 종종 위와 비슷한 상황을 만나게 됩니다. 이번에 소개해 드릴 사례가 바로 그러한데요. 이 웹 사이트는 모든 Biz 로직을 WCF로 옮겨서 서비스로 처리를 하는 상황이었습니다. 그런데, 서비스 공개하고 1달이 지나는 동안 성능 문제로 고생을 하게 되었으며, 이를 해결하기 위해 검색하다가 우연히 '제니퍼 닷넷'을 알게 되어 적용까지 하게 된 것입니다.
아래는, 처음 그 웹 사이트에 '제니퍼 닷넷'을 설치하고 운영되는 모습을 캡쳐한 것입니다.
저녁 시간을 이용해서 모니터링하고 있었기 때문에 요청은 많지 않았지만, 보시는 것처럼 그나마 발생하는 몇몇 요청조차도 스피드 미터에서는 '빨간색' 바(Bar)로 쌓이는 것을 볼 수 있고, 응답시간분포도(X-View)에서는 대다수의 요청들이 5초 이상으로 걸리는 상황을 볼 수 있습니다. (스피드 미터의 '빨간색' 바는 현재 들어온 요청이 8초 이상 처리가 계속 진행 중임을 의미합니다.)
X-View의 몇몇 점들에 대해 '상세 보기'로 들어가면 다음과 같이 WCF 호출 마다 1.5초 정도씩 소요되는 것을 볼 수 있었습니다.
이것만 보면... 분명 WCF에 어떤 문제가 있는 것 같습니다.
IIS는 웹 애플리케이션 내의 파일이 변경되는 경우, In-process 내에서 기존 AppDomain을 내리고 다시 생성하여 웹 애플리케이션을 호스팅하는 기능이 있습니다. '제니퍼 닷넷'에서는 이런 경우를 쉽게 인식할 수 있도록 "장애진단" / "유틸리티" / "시스템 환경 변수" 메뉴를 통해서 Recycle 된 횟수를 보여줍니다.
문제가 있던 그 웹 사이트는 WCF를 호스팅하는 웹 애플리케이션이 지속적으로 Recycle 횟수가 증가하는 현상을 보였고, 아래의 화면은 해당 화면을 캡쳐한 것입니다. (29번째 재생되었음을 나타내고 있으며, 일반적으로는 1이어야 합니다.)
위의 결과를 확인한 후, Recycle을 유발시키는 원인을 찾아보았습니다. 혹시 상상이 가시나요? ... 문제는 다름아닌, WCF 메서드 내에서 '웹 애플리케이션' 폴더의 하위에 '로그 파일'을 쓰고 있었기 때문이었습니다. 따라서, WCF 메서드가 호출될 때마다 IIS는 In-process recycle을 시도하게 되었고 새롭게 로드되는 AppDomain 및 WCF의 호스팅 초기화 부담으로 인해 WCF 메서드의 응답시간들이 지연되는 사태가 발생한 것입니다.
임시로, 로그 파일을 쓰는 폴더에 대해 해당 AppPool 계정만 "Deny" 설정을 한 후 모니터링을 했는데, 결과는 다음과 같이 나왔습니다.
차이점을 한 눈에 확인할 수 있는데요. Recycle이 발생하지 않는 시점부터는 전체적인 응답시간이 아래로 가라앉아서 안정적인 모습을 볼 수 있습니다.
위의 결과를 보기 전, 해당 웹 사이트를 개발한 업체는 그동안 'WCF'에 문제가 있는 것이 아닌가 의심했었다고 합니다. 만약, 위와 같은 원인 파악이 안된 체로 이런 상황이 쭉 진행되었다면... 아마도 그 업체는 지금쯤 WCF를 모두 걷어냈을 지도 모를 일입니다. (그에 따른 비용은 둘째치고, WCF에 대한 신뢰도 하락은 회복 불가능이었을 것입니다.)
결과적으로, 해당 업체는 로그를 남기는 함수 내에서 경로를 수정하기로 했고 아마 지금쯤이면 ^^ 웹 사이트가 정상적으로 서비스들을 호스팅하고 있을 것입니다.
어쨌든... '제니퍼 닷넷'으로 이렇게 금방 성능 문제를 짚어낼 수 있다는 것은... 좀 대단하긴 하지요? ^^
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]