모바일용 웹 사이트에서 발생하는 응답 시간 지연 현상
제니퍼 닷넷으로 웹 사이트를 모니터링하는 경우, 시각적으로 가장 유용한 것이 바로 X-View입니다.
위의 화면을 보면, Y축이 응답시간을 나타내기 때문에 점이 위에 분포하는 것들은 그만큼 응답시간이 느렸다는 것을 의미합니다. Y축 단위가 ms(밀리세컨드)이기 때문에 이 경우에는 6~7초씩 처리 시간이 걸렸음을 알 수 있습니다.
이렇게 처리 시간이 오래 걸리는 요인은 일반적으로 DB나 외부 호출에 의해 병목현상이 발생한 것입니다. 그래서 X-View 상세보기를 통해 어떤 연동 작업에서 느려졌는지를 다음과 같이 확인할 수 있습니다.
그런데, 최근에 고객사로부터 재미있는 현상이 하나 보고되었습니다. 해당 웹 사이트는 "모바일 폰"에서만 접근하는 용도로 만들어졌는데 간헐적으로 응답 시간이 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가지 상황이 유추될 수 있습니다.
- IIS 서버는 HTTP Body를 읽지 못해도 예외를 발생시키지 않는다.
- 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번에 한 번만 그런 식으로 동작했습니다. TCP Stream의 특성상 Header, Body가 나뉘어 전송돼도 한 번에 받는 것이 가능하므로 위의 현상이 그런 의미에서 설명이 가능합니다.
암튼, 실제로 이런 식으로 동작하고 있으니 모바일 환경에서의 특성과 조화(?)만 이룬다면 고객사에서 겪었던 문제가 발생할 수 있는 근거는 마련된 것 같습니다.
좀 더 확실하게 테스트하려면, 모바일 폰을 가지고 다니면서 XMLHTTPRequest.send의 결과 값이 예외가 발생하는 순간과 서버 측에 기록된 GetEntireRawContent의 수행 시간이 맞아 떨어지는 현상이 정말 발생하는지 확인해 보면 됩니다. 음... 이 부분은 나중에 심심해지면 한번 시도해보겠습니다. ^^
(
첨부한 파일은 위의 테스트 코드를 포함하고 있습니다.)
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]