제니퍼 닷넷 적용 사례 (5) - RestSharp 라이브러리의 CPU High 현상
고객사의 웹 사이트가 CPU High 현상으로 서비스가 일시적으로 불능 상태에 빠졌습니다. 평소에는 문제가 없었는데 특정 시간대에 갑자기 사용자가 몰리면서 문제가 표면으로 나타난 것입니다.
제니퍼 제품의 XView를 통해 보니 대략 다음과 같은 패턴으로 장애가 나타났는데요. (실제로는 이보다 더 심각했습니다.)
위의 화면을 보면, 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개의 스레드를 생성해 위의 코드를 실행했더니 다음과 같은 결과를 얻었습니다.
보시는 것처럼, 초당 2,500 ~ 3,200 사이의 처리량을 보였고 아주 단순한 유형의 Restful API를 호출한 것인데도 CPU는 완전히 100%를 전부 쓰고 있습니다. 고객사에 이 상황을 대입해 보면 장애 상황이 이해가 갑니다. test.aspx의 처리에 1,800ms 동안의 CPU 사용량을 보였으니 8개의 코어가 있다고 가정했을 때 겨우 8명의 사용자가 해당 페이지를 동시에 호출하기만 해도 대략 2초 동안은 CPU 점유율이 100%를 치기 때문에 서비스 불능 상황이 발생했던 것입니다.
비교를 위해 RestSharp.RestClient 호출을 닷넷의 WebClient로 바꿔 보았는데요. 결과는 다음과 같습니다.
CPU 사용량이 20%로 안정화되었고 처리량이 8,500 ~ 9,000 사이를 보입니다. (제가 테스트한 네트워크 상태가 안좋아서 그 이상 나오질 않았습니다.)
결론은? RestSharp 라이브러리는 가능한 "클라이언트 측 응용 프로그램"에서만 사용하는 것이 좋습니다. 서비스 유형의 응용 프로그램에서 이를 사용하는 것은 권장되지 않습니다.
(
첨부한 파일은 제가 테스트한 서버/클라이언트 측 코드입니다.)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]