본문 바로가기

.NET/C#

제니퍼 닷넷 적용 사례 (3) - '닷넷'이 문제일까? '닷넷 개발자'가 문제일까?

http://blog.naver.com/techshare/100148008666

위에서 퍼온 글입니다.


아래의 글을 읽어보면,

닷넷 가비지 컬렉션 다시 보기 - 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 에 대한 신뢰도 하락은 회복 불가능이었을 것입니다.)

결과적으로, 해당 업체는 로그를 남기는 함수 내에서 경로를 수정하기로 했고 아마 지금쯤이면 ^^ 웹 사이트가 정상적으로 서비스들을 호스팅하고 있을 것입니다.

어쨌든... '제니퍼 닷넷'으로 이렇게 금방 성능 문제를 짚어낼 수 있다는 것은... 좀 대단하긴 하지요? ^^