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

모바일용 웹 사이트에서 발생하는 응답 시간 지연 현상

제니퍼 닷넷으로 웹 사이트를 모니터링하는 경우, 시각적으로 가장 유용한 것이 바로 X-View입니다.

jennifer_connection_pooling_demo_1.png

위의 화면을 보면, Y축이 응답시간을 나타내기 때문에 점이 위에 분포하는 것들은 그만큼 응답시간이 느렸다는 것을 의미합니다. Y축 단위가 ms(밀리세컨드)이기 때문에 이 경우에는 6~7초씩 처리 시간이 걸렸음을 알 수 있습니다.

이렇게 처리 시간이 오래 걸리는 요인은 일반적으로 DB나 외부 호출에 의해 병목현상이 발생한 것입니다. 그래서 X-View 상세보기를 통해 어떤 연동 작업에서 느려졌는지를 다음과 같이 확인할 수 있습니다.

wcf_recycle_2.png




그런데, 최근에 고객사로부터 재미있는 현상이 하나 보고되었습니다. 해당 웹 사이트는 "모바일 폰"에서만 접근하는 용도로 만들어졌는데 간헐적으로 응답 시간이 50초 이상씩 걸리는 현상이 발생한 것입니다.

문제는, X-View 상세 보기 화면에는 그 원인이 프로파일링 되지 않았다는 점입니다.

-------------------------------------------------------------------------------------------------
[ NO ][ START_TIME ][  GAP][CPU_T]
-------------------------------------------------------------------------------------------------
[0000][10:51:18 068][    0][    0] START
[0000][10:52:07 037][    0][    0] [native:1680], 69 byte(s)
[0001][10:52:07 037][    0][    0] AKL.Framework.ControllerBase.Initialize
[0002][10:52:07 037][    0][    0] AKL.Framework.Core.GetUri
[0003][10:52:07 037][    0][    0] Feelanet.Dev2008.Request [31 ms]
[0004][10:52:07 068][   31][    0] Feelanet.Dev2008.get_Name
[0005][10:52:07 068][    0][    0] Feelanet.Dev2008.get_Age
[0006][10:52:07 068][    0][    0] Feelanet.Dev2008.get_Email
[0007][10:52:07 068][    0][    0] Feelanet.Dev2008.Dispose
[0008][10:52:07 068][    0][    0] END
-------------------------------------------------------------------------------------------------
               TOTAL[49,000][    0]

즉, 개발자가 작성한 코드에 포함된 원격 호출(WCF, .NET Remoting, HTTP 호출, DB 호출... 등)과는 무관한데다 사용자 코드 진입의 초기 시점에 문제가 발생한 것입니다.

다행히 제니퍼 닷넷의 옵션 중에는 응답시간이 지정된 시간 이상 걸리면 StackTrace를 남기는 기능이 있어서 이를 통해 해당 현상이 발생할 때마다 어떤 함수에서 오래 걸리는지 확인할 수 있었는데요.

at System.Web.Hosting.UnsafeIISMethods.MgdSyncReadRequest(IntPtr pHandler, Byte[] pBuffer, Int32 offset, Int32 cbBuffer, Int32& pBytesRead) 
at System.Web.Hosting.IIS7WorkerRequest.ReadEntityCoreSync(Byte[] buffer, Int32 offset, Int32 size) 
at System.Web.HttpRequest.GetEntireRawContent() 
at System.Web.HttpRequest.FillInFormCollection() 
at System.Web.HttpRequest.get_Form() 
at System.Web.HttpRequestWrapper.get_Form() 
at AKL.Framework.UI.MVC.Security.CrossSiteScriptFilter.OnActionExecuting(ActionExecutingContext filterContext) 
...[생략]...
at System.Web.Mvc.Async.AsyncResultWrapper.WrappedAsyncResult`1.End() 
at System.Web.Mvc.MvcHandler.EndProcessRequest(IAsyncResult asyncResult) 
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute() 
at System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously) 
at System.Web.HttpApplication.PipelineStepManager.ResumeSteps(Exception error) 
...[생략]...

콜스택을 봤을 때 AKL.Framework 내부에서 HttpRequest.Form 공용 속성을 접근하는데 이로 인해 System.Web.HttpRequest.GetEntireRawContent가 불려진 것입니다. 이름에서 유추할 수 있듯이 이 메소드는 HTTP payload 전체를 읽어들이는데요. 마지막으로 불리는 System.Web.Hosting.UnsafeIISMethods.MgdSyncReadRequest 메소드를 .NET Reflector로 확인해 보면 Win32 DLL에 구현된 API인 것을 알 수 있습니다.

[DllImport("webengine4.dll", CharSet=CharSet.Unicode)]
internal static extern int MgdReadEntityBody(IntPtr pHandler, byte[] pBuffer, int dwOffset, int dwBytesToRead, bool fAsync, out int pBytesRead, out IntPtr ppAsyncReceiveBuffer);

애석하게도, '관리' 영역을 벗어나 버리니 더 해볼 것이 없군요. ^^




이쯤 되면 해답을 추정하기 위해 최대한 노력을 해봐야 합니다. 이를 위해 우선 GetEntireRawContent 수행 시간이 50초를 넘는 경우 HTTP Header/Body를 덤프로 남기는 코드를 넣어봤습니다.

결과는, 매우 재미있게도 해당 현상이 발생하는 경우엔 언제나 Content-Length에 지정된 길이의 HTTP Body 내용이 없다는 것이었습니다. (참고로, GetEntireRawContent 메소드는 HTTP Post인 경우에만 호출됩니다.)

POST /GetMenuList HTTP/1.1 
Connection: keep-alive 
Content-Length: 23 
Content-Type: application/x-www-form-urlencoded; charset=UTF-8 
Accept: application/json, text/javascript, */*; q=0.01 
Accept-Charset: utf-8, iso-8859-1, utf-16, *;q=0.7 
Accept-Encoding: gzip,deflate 
Accept-Language: ko-KR, en-US 
Cookie: ASP.NET_SessionId=...[생략]...]; NFMPT.reqCnt=0 
Host: m.abnkorea.co.kr 
Referer: http://m.test.co.kr/MapDetail
User-Agent: Mozilla/5.0 (Linux; U; Android 4.1.2; ko-kr; SHV-E220S Build/JZO54K) AppleWebKit/534.30 (KHTML, like Gecko) Version/4.0 Mobile Safari/534.30 
Origin: http://m.test.co.kr 
X-Requested-With: XMLHttpRequest


물론, 정상적으로 수행된 /GetMenuList의 경우에는 HTTP Body가 포함되어 있었습니다.

확신할 수는 없지만, 이 현상을 설명하는 한 가지 시나리오는 모바일 클라이언트에서 HTTP Header까지는 정상적으로 보냈으나 그다음 Body를 보내는 Socket.Send 단계에서 통신 불가 상태로 빠져 버린 것입니다. 어쨌든 3G 네트워크는 유선망과 비교해 안정성은 낮으므로 그나마 그렇게라도 해석 가능합니다.

3G 모바일 네트워크의 이해 
; http://helloworld.naver.com/helloworld/111111




그런데, 개인적으로 궁금함이 생겼습니다. 위의 과정에서 보면 2가지 상황이 유추될 수 있습니다.

  1. IIS 서버는 HTTP Body를 읽지 못해도 예외를 발생시키지 않는다.
  2. IIS 서버는 클라이언트로부터 HTTP 헤더만 읽어도 요청 처리를 시작한다.

무엇보다 첫 번째 문제가 더 궁금했습니다. 왜냐하면, IIS 측에서 Body를 읽는 시도에서 성공하지 못했다면 오히려 Time-out 같은 예외를 냈을 것 같기 때문입니다.

이를 확인하기 위해 TCP Socket을 만들어 다음과 같이 클라이언트 코드를 만들어 보았습니다.

static void Main(string[] args)
{
    Socket socket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp);
    EndPoint serverEP = new IPEndPoint(IPAddress.Loopback, 8010);

    socket.Connect(serverEP);

    string request = "POST / HTTP/1.1\nHost: 127.0.0.1\n";
    request += "Content-Length: 5\n";
    request += "Content-Type: application/x-www-form-urlencoded; charset=UTF-8\n\n";

    byte[] sendBuffer = Encoding.UTF8.GetBytes(request);

    // HTTP 헤더를 먼저 보내고,
    socket.Send(sendBuffer);

    // 60초 대기
    Thread.Sleep(1000 * 60);

    // 그냥 종료
}

그런 다음 ASP.NET 웹 사이트의 global.asax.cs에 다음과 같은 코드를 넣었습니다.

public class Global : System.Web.HttpApplication
{
    void Application_Start(object sender, EventArgs e)
    {
        // Code that runs on application startup
    }

    void Application_BeginRequest(object sender, EventArgs e)
    {
        System.Diagnostics.Trace.WriteLine("BeginRequest ================================");
    }

    // ... [생략] ...
}

클라이언트 측에서 HTTP 헤더만을 보낸 시점에 디버깅 화면으로 "BeginRequest =====..." 로그가 출력되는 것을 확인할 수 있었습니다. 또한 결국에 HTTP Body를 못 받았음에도 불구하고 어떠한 예외도 발생하지 않았습니다.

이로써 2가지 모두 확인이 되었군요. ^^




그런데, 아직도 궁금한 것이 하나 남았습니다. 정말로 모바일 브라우저 측에서 XMLHttpRequest가 그런 식으로 Header와 Body를 나눠서 전송하느냐는 것인데요.

이를 재현하기 위해 간단하게 TCP 웹 서버를 다음과 같이 만들고,

static void Main(string[] args)
{
    using (Socket srvSocket = new Socket(AddressFamily.InterNetwork, SocketType.Stream, ProtocolType.Tcp))
    {
        Console.WriteLine("http://localhost:8000으로 방문해 보세요.");

        IPEndPoint endPoint = new IPEndPoint(IPAddress.Any, 8000);

        srvSocket.Bind(endPoint);
        srvSocket.Listen(10);

        while (true)
        {
            Socket clntSocket = srvSocket.Accept();
            ThreadPool.QueueUserWorkItem(httpProcessFunc, clntSocket);
        }
    }
}

private static void httpProcessFunc(object state)
{
    Socket socket = state as Socket;

    byte[] reqBuf = new byte[4096];

    int nRecv = socket.Receive(reqBuf);
    string input = Encoding.UTF8.GetString(reqBuf, 0, nRecv);

    // HTTP Body까지 한 번에 읽었는지 확인
    bool hasBody = HasBody(input);

    Console.WriteLine("1: " + input);

    if (hasBody == false)
    {
        // HTTP Body가 이전에 안 읽혔으면 마저 읽어들인다.
        nRecv = socket.Receive(reqBuf);
        input = Encoding.UTF8.GetString(reqBuf, 0, nRecv);
        Console.WriteLine("2: " + input);
    }

    string header = "HTTP/1.0 200 OK\nContent-Type: text/html; charset=UTF-8\n\n";
    string body = "<html><body><mark>테스트 HTML</mark> 웹 페이지입니다.</body></html>";

    byte[] respBuf = Encoding.UTF8.GetBytes(header + body);
    socket.Send(respBuf);
    socket.Close();
}

private static bool HasBody(string input)
{
    string splitter = "\r\n\r\n";
    int pos = input.IndexOf(splitter);
    if (pos + splitter.Length == input.Length)
    {
        return false;
    }

    return true;
}

그다음, 로컬 PC의 폴더에 다음과 같은 HTML 페이지를 만들었습니다.

<html>

    <head>

        <script language="javascript" type="text/javascript">

            function btn_Click() {
                var xmlObj = new XMLHttpRequest();
                xmlObj.open("POST", "http://localhost:8000/", false);
                xmlObj.send("test");
            }

        </script>

    </head>

    <body>

        <span onclick="btn_Click()">Click!</span>

    </body>

</html>

준비가 되었으니 테스트를 시작해야죠. ^^ IE 웹 브라우저를 실행해서 HTML 페이지를 로드한 후 Click 텍스트를 마우스로 눌러보았는데요. 결과가 재미있습니다. ^^

한 번은 Header + Body가 모두 전송되어오고, 그다음 한 번은 정확히 Header만 먼저 전송된 후 Body가 나뉘어져 Receive에 읽혀졌습니다.

물론, 이것은 IE 웹 브라우저를 대상으로 테스트가 되었기 때문에 안드로이드 모바일 환경에서는 다를 수 있지만 그래도 브라우저들 간에 이런 식으로 구현되어졌음을 유추해 볼 수는 있습니다.

참고로, 이런 현상에 대한 Q&A 글도 있군요. ^^

When does a browser send HTTP payload separately from the HTTP request?
; http://serverfault.com/questions/337949/when-does-a-browser-send-http-payload-separately-from-the-http-request

위의 글에서는 XMLHTTPRequest가 언제나 Header와 Body를 나눠서 보낸다고 되어 있는데요. IE의 경우에는 2번에 한 번만 그런 식으로 동작했습니다.

암튼, 실제로 이런 식으로 동작하고 있으니 모바일 환경에서의 특성과 조화(?)만 이룬다면 고객사에서 겪었던 문제가 발생할 수 있는 근거는 마련된 것 같습니다.

좀 더 확실하게 테스트하려면, 모바일 폰을 가지고 다니면서 XMLHTTPRequest.send의 결과 값이 예외가 발생하는 순간과 서버 측에 기록된 GetEntireRawContent의 수행 시간이 맞아 떨어지는 현상이 정말 발생하는지 확인해 보면 됩니다. 음... 이 부분은 나중에 심심해지면 한번 시도해보겠습니다. ^^

(첨부한 파일은 위의 테스트 코드를 포함하고 있습니다.)




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

[연관 글]


donaricano-btn



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

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

비밀번호

댓글 쓴 사람
 



2013-04-04 09시48분
[박중석] 마치 '미드 CSI 과학 수사대' 혹은 '그것이 알고 싶다'를 보고 있는 것처럼 빠져드는 느낌의 아티클이네요. 이같이 문제를 접근하고 해결하는 값진 경험을 공유해 주셔서 감사합니다! (항상 올려주시는 아티클 잘 보고 있습니다. 댓글을 오랜만에 달아서... 쿨럭)
[손님]
2013-04-05 04시18분
[유수석] IIS가 Header를 먼저 읽고 Body를 읽는 다는 것은 이해가 갑니다. Header를 읽어야 Body를 얼마만큼 읽어야 하는지 알 수 있기 때문이죠(Content-Length 등).
TCP 프로토콜이 항상 send 한 만큼의 버퍼를 전송하는 것은 아니라고 알고 있습니다. TCP 윈도우의 크기에 따라서 버퍼에 일정 양이 채워질 때까지 기다리거나 채워지지 않더라도 일정 시간이 지나면 패킷을 전송하곤 하죠. 이런 이유에서 Header와 Body가 한번에 전송될 수도 그렇지 않을 수도 있다고 봅니다.
그래서 HTTP 서버에서 문제가 되는 건 클라이언트가 Header에 명시된 크기보다 작은 Body를 보내면 다음 HTTP Request 역시 꼬일 수 있다는 겁니다. IIS에서는 이런 잘못된 HTTP Request를 어떻게 복구하는지 궁금하긴 하네요. 흥미로운 글이었습니다. ^^
[손님]
2013-04-05 03시18분
@박중석 님 재미있는 표현 감사드립니다. ^^

@유수석 님 ^^ 넵. 말씀하신 대로 TCP의 Stream 방식과 Nagle 알고리즘 등의 영향으로 Message-Boundary가 지켜지지 않겠지만, 그래도 Send(Header), Send(Body)가 정확히 끊어서 테스트된 것은 아무래도 클라이언트 측에서 Send 자체를 그렇게 한 것이 아닌가 생각됩니다.

그리고 Content-Length에 대해서는, HTTP 헤더의 Connection 값이 Keep-Alive 또는 Close에 따라 IIS의 대처 방법이 다를 것 같습니다. Close인 경우는 위의 글에 나타난 현상이 전부일 것 같고, Keep-Alive인 경우 말씀하신 것과 같은 문제가 발생할 수 있을 텐데요. 이전의 HTTP Body가 적게 전송되었다면 Keep-Alive로 이어지는 다음의 HTTP Header 일부가 Body로 편입될 듯 싶습니다. 따라서 나머지 HTTP Header부터 새로운 HTTP Request로 인식하려고 시도할 텐데 적합한 HTTP Method 요청이 아닐 것이므로 Invalid Request 정도로 처리하고 곧바로 연결을 끊지 않을까 예상해 봅니다. ^^
정성태
2013-04-05 03시58분
[유수석] 물론, 클라이언트가 header와 body를 서로다른 send 호출로 구현했을 가능성이 높습니다. 하지만 클라이언트가 Header와 body를 각각 send 호출로 보내더라도 서버는 하나의 receive로 둘을 받을 수 있다는 거죠. IIS 역시 용빼는 재주는 없을테니 다음 HTTP Request의 적합한 시작이 나올때까지 TCP 스트림에서 계속 읽어서 버리는 수 밖에 없을거라 생각이 듭니다.
[손님]
2013-04-06 01시42분
넵. ^^ @유수석 님의 말씀처럼 "클라이언트가 header와 body를 서로 다른 send 호출로 구현했을 가능성이 높습니다"라는 것이 제가 이번 테스트에서 재미있게 생각했던 부분입니다. 어차피 IIS(TCP) 서버 측에서는 Receive를 호출해 스트림으로 읽어들여 처리해야 할 텐데, 굳이 클라이언트 측에서 Header와 Body를 끊어서 보냈어야 할 이유가 있을까 싶습니다. 아마도 제가 웹 브라우저 개발자였다면 전송될 Body의 크기가 일정 범위 이내라면 (본문의 예제처럼 단지 'test'처럼 짧은) 한 번에 보내도록 했겠고, 심지어 넘어가더라도 Send(Header + Body의 일부), Send(Body...)처럼 구현했을 것 같습니다. (물론, Cookie가 크면 Header조차도 나뉘어 전송되겠고요. ^^)

실제로 제가 생각했던 것처럼 구현했다면, 아마도 고객사 사이트와 같은 문제는 발생하지 않았을 수도 있습니다.
정성태

[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
12746정성태7/31/202138개발 환경 구성: 588. 네트워크 장비 환경을 시뮬레이션하는 Packet Tracer 프로그램 소개
12745정성태7/31/202113개발 환경 구성: 587. Azure Active Directory - tenant의 관리자 계정 로그인 방법
12744정성태7/30/202119개발 환경 구성: 586. Azure Active Directory에 연결된 App 목록을 확인하는 방법?
12743정성태7/30/202135.NET Framework: 1083. Azure Active Directory - 외부 Token Cache 저장소를 사용하는 방법파일 다운로드1
12742정성태7/30/202118개발 환경 구성: 585. Azure AD 인증을 위한 사용자 인증 유형
12741정성태7/29/202169.NET Framework: 1082. Azure Active Directory - Microsoft Graph API 호출 방법파일 다운로드1
12740정성태7/29/202131오류 유형: 747. SharePoint - InvalidOperationException 0x80131509
12739정성태7/28/202127오류 유형: 746. Azure Active Directory - IDW10106: The 'ClientId' option must be provided.
12738정성태7/28/202126오류 유형: 745. Azure Active Directory - Client credential flows must have a scope value with /.default suffixed to the resource identifier (application ID URI).
12737정성태7/28/202129오류 유형: 744. Azure Active Directory - The resource principal named api://...[client_id]... was not found in the tenant
12736정성태7/28/202136오류 유형: 743. Active Azure Directory에서 "API permissions"의 권한 설정이 "Not granted for ..."로 나오는 문제
12735정성태7/27/202171.NET Framework: 1081. C# - Azure AD 인증을 지원하는 데스크톱 애플리케이션 예제(Windows Forms)파일 다운로드1
12734정성태7/26/202180스크립트: 20. 특정 단어로 시작하거나/끝나는 문자열을 포함/제외하는 정규 표현식 - Look-around
12733정성태7/23/202195.NET Framework: 1081. Self-Contained/SingleFile 유형의 .NET Core/5+ 실행 파일을 임베딩한다면?파일 다운로드2
12732정성태7/23/202146오류 유형: 742. SharePoint - The super user account utilized by the cache is not configured.
12731정성태7/23/202156개발 환경 구성: 584. Add Internal URLs 화면에서 "Save" 버튼이 비활성화 된 경우
12730정성태7/23/202161개발 환경 구성: 583. Visual Studio Code - Go 코드에서 입력을 받는 경우
12729정성태7/22/202169.NET Framework: 1080. xUnit 단위 테스트에 메서드/클래스 수준의 문맥 제공 - Fixture
12728정성태7/22/202172.NET Framework: 1079. MSTestv2 단위 테스트에 메서드/클래스/어셈블리 수준의 문맥 제공
12727정성태7/21/2021138.NET Framework: 1078. C# 단위 테스트 - MSTestv2/NUnit의 Assert.Inconclusive 사용법(?)
12726정성태7/21/2021113VS.NET IDE: 169. 비주얼 스튜디오 - 단위 테스트 선택 시 MSTestv2 외의 xUnit, NUnit 사용법
12725정성태7/21/202157오류 유형: 741. Failed to find the "go" binary in either GOROOT() or PATH
12724정성태7/21/2021150개발 환경 구성: 582. 윈도우 환경에서 Visual Studio Code + Go (Zip) 개발 환경 [1]
12723정성태7/21/202162오류 유형: 740. SharePoint - Alternate access mappings have not been configured 경고
12722정성태7/20/2021107오류 유형: 739. MSVCR110.dll이 없어 exe 실행이 안 되는 경우
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...