Microsoft MVP성태의 닷넷 이야기
글쓴 사람
정성태 (techsharer at outlook.com)
홈페이지
첨부 파일

제니퍼 닷넷 적용 사례 (5) - RestSharp 라이브러리의 CPU High 현상

고객사의 웹 사이트가 CPU High 현상으로 서비스가 일시적으로 불능 상태에 빠졌습니다. 평소에는 문제가 없었는데 특정 시간대에 갑자기 사용자가 몰리면서 문제가 표면으로 나타난 것입니다.

제니퍼 제품의 XView를 통해 보니 대략 다음과 같은 패턴으로 장애가 나타났는데요. (실제로는 이보다 더 심각했습니다.)

restsharp_poor_perf_1.png

위의 화면을 보면, 10초 시간 대에 빨간색 점으로 나타나는데 모두 자체적으로 정의된 10초 time-out에 걸려 오류가 발생한 것들입니다.

제니퍼 분석 결과, 해당 시간대에 CPU를 가장 많이 소비한 응용 프로그램이 밝혀졌고 이를 "test.aspx"라고 가정하겠습니다. 해당 페이지의 응답 기록을 보니 평소에도 2,000ms 정도가 걸렸고 특이하게도 그 응답 시간 동안 CPU 소비량이 1,800ms로 90% 정도가 CPU-intensive한 작업을 하고 있었습니다.

일단 범인은 밝혀졌으므로 이젠 관심사가 test.aspx 소스코드의 어떤 부분에서 잘못된 것인지로 옮겨갔습니다.

다행히, 해당 웹 애플리케이션 서비스 장애가 발생한 시점에 남겨진 "서비스 덤프"를 통해 쉽게 문제에 접근할 수 있었습니다. 지난번 사례에서도 "서비스 덤프"가 장애 원인을 밝히는 데 결정적인 역할을 했었는데... 이번에도 그랬습니다. ^^

제니퍼 닷넷 적용 사례 (2) - 웹 애플리케이션 hang 의 원인을 알려주다.
; https://www.sysnet.pe.kr/2/0/1117

이번 고객사의 서비스 덤프 내용을 보니, test.aspx 페이지의 경우 대부분 다음과 같이 RestSharp.Deserializers.JsonDeserializer, System.Text.RegularExpressions 쪽의 호출 스택을 갖고 있다는 것이었습니다.

D:192.168.0.5:20151005/134415:2153:52.0%:LA1:TXEXED:/test.aspx::WebReq.http://mytestsrv/test.asmx:::::-5268713217693983903::-5268713217693983903
   위치: System.Threading.Monitor.Enter(Object obj)
   위치: System.Text.RegularExpressions.Regex.LookupCachedAndUpdate(String key)
   위치: System.Text.RegularExpressions.Regex..ctor(String pattern, RegexOptions options, TimeSpan matchTimeout, Boolean useCache)
   위치: RestSharp.Extensions.StringExtensions.AddUnderscores(String pascalCasedWord)
   위치: RestSharp.Extensions.StringExtensions.<GetNameVariants>d__0.MoveNext()
   위치: System.Linq.Enumerable.Contains[TSource](IEnumerable`1 source, TSource value, IEqualityComparer`1 comparer)
   위치: System.Linq.Enumerable.FirstOrDefault[TSource](IEnumerable`1 source, Func`2 predicate)
   위치: RestSharp.Extensions.ReflectionExtensions.FindEnumValue(Type type, String value, CultureInfo culture)
   위치: RestSharp.Deserializers.JsonDeserializer.ConvertValue(Type type, Object value)
   위치: RestSharp.Deserializers.JsonDeserializer.Map(Object target, IDictionary`2 data)
   위치: RestSharp.Deserializers.JsonDeserializer.CreateAndMap(Type type, Object element)
   위치: RestSharp.Deserializers.JsonDeserializer.ConvertValue(Type type, Object value)
...[이하 생략]...

JSON 관련 직렬화(Serialization) 작업에 정규 표현식(Regular Expression)을 사용했다면 왠지 모르게 CPU 100% 현상의 주요 원인이었음을 짐작케 해줍니다.

이 사실을 고객 측과 공유했고 현재 관련 라이브러리를 제거하고 정상적인 서비스에 들어갔다고 합니다. ^^




회사로 복귀한 후, "하지만, 정말 그게 원인일까???" 하는 의문이 생겼습니다. 왜냐하면 콜스택에 남았다고 해서 CPU 소비량이 크다는 증거가 아니기 때문입니다. 하필 콜스택을 남기는 순간에 그것이 실행되었을 수도 있으므로 확실한 증거를 얻기 위해 간단하게 테스트 코드를 작성해 보았습니다.

이를 위해 WCF Restful 서비스를 하는 서버 측 코드를 작성하고,

using System;
using System.ServiceModel;
using System.ServiceModel.Web;

namespace ConsoleApplication2
{
    // http://blog.sublogic.com/2010/07/15/making-a-wcf-rest-stand-alone-service-exe-from-scratch-part-1-of-4-creating-the-minimal-bare-service/
    [ServiceContract]
    public class MyService
    {
        [WebGet(UriTemplate = "say/{something}")]
        public string AnswerBack(string something)
        {
            return "You said: " + something;
        }
    }

    class Program
    {
        static void Main(string[] args)
        {
            using (var serviceHost = new ServiceHost(typeof(MyService)))
            {
                serviceHost.Open();
                Console.WriteLine("Hit Enter when done");
                Console.ReadLine();
            }            
        }
    }
}

다른 컴퓨터에 띄워놓은 후 다음의 RestSharp 클라이언트 측 코드를 작성해 실행해 보았습니다.

using System;
using System.Net;
using System.Threading;

namespace ConsoleApplication1
{
    class Program
    {
        static int _count = 0;

        static void Main(string[] args)
        {
            System.Net.ServicePointManager.DefaultConnectionLimit = 40000;

            int loadCount = (int)(Environment.ProcessorCount * 1.5);

            CreateTest(loadCount, restThreadFunc);
            
            ThreadPool.QueueUserWorkItem(Printthroughput);

            Console.ReadLine();
        }

        private static void Printthroughput(object obj)
        {
            int old = 0;

            while (true)
            {
                Thread.Sleep(1000);

                int current = _count;
                int reqPerSecond = current - old;
                Console.WriteLine("Req / Second: " + reqPerSecond);

                old = current;
            }
        }

        private static void CreateTest(int threadCount, ThreadStart action)
        {
            for (int i = 0; i < threadCount; i ++)
            {
                Thread t = new Thread(action);
                t.IsBackground = true;
                t.Start();
            }
        }

        private static void restThreadFunc()
        {
            while (true)
            {
                RestSharp.RestClient client = new RestSharp.RestClient("http://192.168.0.6:8077");
                RestSharp.RestRequest request = new RestSharp.RestRequest("/testing/say/hello", RestSharp.Method.GET);

                string result = client.Execute(request).Content;
                Interlocked.Increment(ref _count);
            }
        }
    }
}

제 컴퓨터가 하이퍼스레딩이 활성화된 상태에서 8개의 논리 코어가 있어 12개의 스레드를 생성해 위의 코드를 실행했더니 다음과 같은 결과를 얻었습니다.

restsharp_poor_perf_2.png

보시는 것처럼, 초당 2,500 ~ 3,200 사이의 처리량을 보였고 아주 단순한 유형의 Restful API를 호출한 것인데도 CPU는 완전히 100%를 전부 쓰고 있습니다. 고객사에 이 상황을 대입해 보면 장애 상황이 이해가 갑니다. test.aspx의 처리에 1,800ms 동안의 CPU 사용량을 보였으니 8개의 코어가 있다고 가정했을 때 겨우 8명의 사용자가 해당 페이지를 동시에 호출하기만 해도 대략 2초 동안은 CPU 점유율이 100%를 치기 때문에 서비스 불능 상황이 발생했던 것입니다.

비교를 위해 RestSharp.RestClient 호출을 닷넷의 WebClient로 바꿔 보았는데요. 결과는 다음과 같습니다.

restsharp_poor_perf_3.png

CPU 사용량이 20%로 안정화되었고 처리량이 8,500 ~ 9,000 사이를 보입니다. (제가 테스트한 네트워크 상태가 안좋아서 그 이상 나오질 않았습니다.)




결론은? RestSharp 라이브러리는 가능한 "클라이언트 측 응용 프로그램"에서만 사용하는 것이 좋습니다. 서비스 유형의 응용 프로그램에서 이를 사용하는 것은 권장되지 않습니다.

(첨부한 파일은 제가 테스트한 서버/클라이언트 측 코드입니다.)




[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]







[최초 등록일: ]
[최종 수정일: 6/27/2021]

Creative Commons License
이 저작물은 크리에이티브 커먼즈 코리아 저작자표시-비영리-변경금지 2.0 대한민국 라이센스에 따라 이용하실 수 있습니다.
by SeongTae Jeong, mailto:techsharer at outlook.com

비밀번호

댓글 작성자
 




... [61]  62  63  64  65  66  67  68  69  70  71  72  73  74  75  ...
NoWriterDateCnt.TitleFile(s)
12100정성태1/3/20209115.NET Framework: 875. .NET 3.5 이하에서 IntPtr.Add 사용
12099정성태1/3/202011395디버깅 기술: 151. Windows 10 - Process Explorer로 확인한 Handle 정보를 windbg에서 조회 [1]
12098정성태1/2/202010997.NET Framework: 874. C# - 커널 구조체의 Offset 값을 하드 코딩하지 않고 사용하는 방법 [3]
12097정성태1/2/20209535디버깅 기술: 150. windbg - Wow64, x86, x64에서의 커널 구조체(예: TEB) 구조체 확인
12096정성태12/30/201911546디버깅 기술: 149. C# - DbgEng.dll을 이용한 간단한 디버거 제작 [1]
12095정성태12/27/201912892VC++: 135. C++ - string_view의 동작 방식
12094정성태12/26/201911065.NET Framework: 873. C# - 코드를 통해 PDB 심벌 파일 다운로드 방법
12093정성태12/26/201911108.NET Framework: 872. C# - 로딩된 Native DLL의 export 함수 목록 출력파일 다운로드1
12092정성태12/25/201910518디버깅 기술: 148. cdb.exe를 이용해 (ntdll.dll 등에 정의된) 커널 구조체 출력하는 방법
12091정성태12/25/201912046디버깅 기술: 147. pdb 파일을 다운로드하기 위한 symchk.exe 실행에 필요한 최소 파일 [1]
12090정성태12/24/201910633.NET Framework: 871. .NET AnyCPU로 빌드된 PE 헤더의 로딩 전/후 차이점 [1]파일 다운로드1
12089정성태12/23/201911392디버깅 기술: 146. gflags와 _CrtIsMemoryBlock을 이용한 Heap 메모리 손상 여부 체크
12088정성태12/23/201910350Linux: 28. Linux - 윈도우의 "Run as different user" 기능을 shell에서 실행하는 방법
12087정성태12/21/201910840디버깅 기술: 145. windbg/sos - Dictionary의 entries 배열 내용을 모두 덤프하는 방법 (do_hashtable.py) [1]
12086정성태12/20/201912878디버깅 기술: 144. windbg - Marshal.FreeHGlobal에서 발생한 덤프 분석 사례
12085정성태12/20/201910583오류 유형: 586. iisreset - The data is invalid. (2147942413, 8007000d) 오류 발생 - 두 번째 이야기 [1]
12084정성태12/19/201911215디버깅 기술: 143. windbg/sos - Hashtable의 buckets 배열 내용을 모두 덤프하는 방법 (do_hashtable.py) [1]
12083정성태12/17/201912501Linux: 27. linux - lldb를 이용한 .NET Core 응용 프로그램의 메모리 덤프 분석 방법 [2]
12082정성태12/17/201912335오류 유형: 585. lsof: WARNING: can't stat() fuse.gvfsd-fuse file system
12081정성태12/16/201914060개발 환경 구성: 465. 로컬 PC에서 개발 중인 ASP.NET Core 웹 응용 프로그램을 다른 PC에서도 접근하는 방법 [5]
12080정성태12/16/201911972.NET Framework: 870. C# - 프로세스의 모든 핸들을 열람
12079정성태12/13/201913171오류 유형: 584. 원격 데스크톱(rdp) 환경에서 다중 또는 고용량 파일 복사 시 "Unspecified error" 오류 발생
12078정성태12/13/201913155Linux: 26. .NET Core 응용 프로그램을 위한 메모리 덤프 방법 [3]
12077정성태12/13/201912661Linux: 25. 자주 실행할 명령어 또는 초기 환경을 "~/.bashrc" 파일에 등록
12076정성태12/12/201910856디버깅 기술: 142. Linux - lldb 환경에서 sos 확장 명령어를 이용한 닷넷 프로세스 디버깅 - 배포 방법에 따른 차이
12075정성태12/11/201911695디버깅 기술: 141. Linux - lldb 환경에서 sos 확장 명령어를 이용한 닷넷 프로세스 디버깅
... [61]  62  63  64  65  66  67  68  69  70  71  72  73  74  75  ...