제니퍼 닷넷 적용 사례 (8) - CPU high와 DB 쿼리 성능에 문제가 함께 있는 사이트
한 고객사의 X-View 화면입니다.
새벽 시간을 지나, 업무 시간이 되면서 수백 초의 응답시간을 갖는 점들로 가득한 상태입니다. 당연히 고객사는 원인을 밝히고 싶어 했는데요. (그런데... 정말 개인적인 의문인데, 저런 상황에서는 이성적인 개발자라면 조금만 살펴봐도 원인이 나오지 않을까요? ^^) 문제가 되는 페이지는 2개로 압축할 수 있었고 사실 거의 그 2개만이 사용되는 경우가 많았습니다.
우선, 웹 페이지 하나(편의상 testA.aspx)의 경우 DB Fetch 시간이 너무 길었습니다. 보통 130초가 넘는 시간을 보였는데요, 프로파일링 출력에는 그 원인을 알려주는 쿼리문이 보였습니다. 게다가 저 페이지가 자주 불렸고 저런 현상이 계속 나타났기 때문에 실시간 액티브 서비스를 통해 스택 트레이스를 확인하면 다음과 같이 Oracle DB 쿼리 수행 중에 동작이 멈춰 있음을 확인할 수 있었습니다.
System.Data.Common.UnsafeNativeMethods.OCIStmtFetch(OciHandle stmtp, OciHandle errhp, UInt32 nrows, FETCH orientation, MODE mode)
System.Data.OracleClient.TracedNativeMethods.OCIStmtFetch(OciHandle stmtp, OciHandle errhp, Int32 nrows, FETCH orientation, MODE mode)
System.Data.OracleClient.OracleDataReader.ReadInternal()
System.Data.OracleClient.OracleDataReader.Read()
System.Data.Common.DataAdapter.FillLoadDataRow(SchemaMapping mapping)
System.Data.Common.DataAdapter.FillFromReader(DataSet dataset, DataTable datatable, String srcTable, DataReaderContainer dataReader, Int32 startRecord, Int32 maxRecords, DataColumn parentChapterColumn, Object parentChapterValue)
System.Data.Common.DataAdapter.Fill(DataSet dataSet, String srcTable, IDataReader dataReader, Int32 startRecord, Int32 maxRecords)
System.Data.Common.DbDataAdapter.FillInternal(DataSet dataset, DataTable[] datatables, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
System.Data.Common.DbDataAdapter.Fill(DataSet dataSet, Int32 startRecord, Int32 maxRecords, String srcTable, IDbCommand command, CommandBehavior behavior)
System.Data.Common.DbDataAdapter.Fill(DataSet dataSet)
myservice.DoGetResult(Object sender, EventArgs e)
System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
System.Web.UI.Page.ProcessRequest()
System.Web.UI.Page.ProcessRequest(HttpContext context)
ASP.testA_aspx.ProcessRequest(HttpContext context)
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
System.Web.HttpApplication.ApplicationStepManager.ResumeSteps(Exception error)
System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData)
System.Web.HttpRuntime.ProcessRequestInternal(HttpWorkerRequest wr)
System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr ecb, Int32 iWRType)
그런데, 진짜 심각한 문제가 하나 더 있었습니다. 역시나 이것도 자주 불리는 페이지였는데(편의상 TestB.aspx) CPU 소비가 상당했다는 점이 특이합니다. 이것은 다음의 X-View 상세 보기 화면에서 확인할 수 있는데요,
보는 바와 같이 658,667ms의 경우 650초 동안 CPU가 사용됐으니 거의 10분 동안 CPU 코어 하나가 요청 하나 처리하는데 점유가 된 것입니다.
자, 그렇다면 이런 경우 어떻게 제니퍼로 원인을 찾을 수 있을까요? 사실 위의 화면에도 나오지만, "Stack trace" 탭에 99개의 호출 스택이 있음을 보여주고 있는데 바로 그 기능이 "자동 스택트레이스"라는 것입니다.
제니퍼(JENNIFER) 자동 스택트레이스(Auto Stacktrace) 사용하기
; https://jennifersoft.tistory.com/63
따라서, 예를 들어 10초 이상 수행하는 요청이 있다면 그때부터 1초마다 호출 스택을 남기는 식으로 옵션을 설정할 수 있는데요, 그렇게 되면 위의 화면 하단에서 볼 수 있는 시간별 호출 스택을 열람할 수 있습니다. 그리고, 어떤 메서드의 호출이 문제였는지를 여러 개의 호출 스택에서 공통적으로 보이는 메서드 하나를 찾아내는 것으로 (100%라고는 할 수 없지만) 단서를 찾을 수 있습니다.
문제의 고객사는 데이터 그리드의 항목들을 Excel로 출력해 주는 DevExpress의 메서드로 밝혀졌습니다.
System.Drawing.SafeNativeMethods.Gdip.GdipMeasureString(HandleRef graphics, String textString, Int32 length, HandleRef font, GPRECTF& layoutRect, HandleRef stringFormat, GPRECTF& boundingBox, Int32& codepointsFitted, Int32& linesFilled)
System.Drawing.Graphics.MeasureString(String text, Font font, SizeF layoutArea, StringFormat stringFormat)
DevExpress.XtraPrinting.Native.Measurer.MeasureString(String text, Font font, Single width, StringFormat stringFormat, GraphicsUnit pageUnit)
DevExpress.XtraPrinting.Native.Measurement.MeasureString(String text, Font font, Single width, StringFormat stringFormat, GraphicsUnit pageUnit)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewPrinter.GetTextSize(String text, GridViewExportAppearance style, Int32 maxWidth)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewPrinter.CalcCellWidth(GridViewColumn column, Int32 rowIndex)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewPrinter.CalcColumnWidth(GridViewColumn column)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewPrinter.CalcBrickSizes()
DevExpress.Web.ASPxGridView.Export.Helper.GridViewPrinter.BeforeCreate()
DevExpress.Web.ASPxGridView.Export.Helper.GridViewLink.AddPrinter(ASPxGridView grid, Int32 detailGridIndent)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewLink.get_ActivePrinter()
DevExpress.Web.ASPxGridView.Export.Helper.GridViewLink.CreateDetailHeader(BrickGraphics graph)
DevExpress.XtraPrinting.LinkBase.CreateDocumentCore(Boolean buildPagesInBackground)
DevExpress.XtraPrinting.LinkBase.CreateDocument(Boolean buildPagesInBackground)
DevExpress.Web.ASPxGridView.Export.Helper.GridViewLink.CreatePS()
DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.CreatePS()
DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.WriteXlsCore(Stream stream, ExportOptionsBase exportOptions)
DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.WriteToResponse(String fileName, Boolean saveAsFile, String fileFormat, ExportToStream getStream, ExportOptionsBase options)
DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.WriteXlsToResponse(String fileName, Boolean saveAsFile)
System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
System.Web.UI.Page.ProcessRequest()
System.Web.UI.Page.ProcessRequest(HttpContext context)
ASP.testB_aspx.ProcessRequest(HttpContext context)
System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
System.Web.HttpApplication.ExecuteStep(IExecutionStep step, Boolean& completedSynchronously)
System.Web.HttpApplication.ApplicationStepManager.ResumeSteps(Exception error)
System.Web.HttpApplication.System.Web.IHttpAsyncHandler.BeginProcessRequest(HttpContext context, AsyncCallback cb, Object extraData)
System.Web.HttpRuntime.ProcessRequestInternal(HttpWorkerRequest wr)
System.Web.Hosting.ISAPIRuntime.ProcessRequest(IntPtr ecb, Int32 iWRType)
검색해 보면 아마도 아래와 같은 식으로 사용했을 것으로 보입니다.
C# (CSharp) ASPxGridViewExporter Examples
; https://csharp.hotexamples.com/examples/-/ASPxGridViewExporter/-/php-aspxgridviewexporter-class-examples.html
그나저나, 도대체 얼마나 큰 용량의 데이터를 Excel로 변환하는 것인지는 알 수 없지만 어쨌든 분명한 건 ASPxGridViewExporter.WriteXlsToResponse에서 CPU 시간을 소비하고 있다는 것입니다.
여기서 한 가지 더 재미있는 것은, 해당 고객사의 경우 위의 2가지 문제 이외에도 유난히 많은 System.Web.HttpUnhandledException 예외가 있었다는 점입니다. 이에 대한 예외 메시지를 보면,
System.Web.HttpUnhandledException (0x80004005): Exception of type 'System.Web.HttpUnhandledException' was thrown. ---> System.Web.HttpException (0x800703E3): An error occurred while communicating with the remote host. The error code is 0x800703E3.
at System.Web.Hosting.ISAPIWorkerRequestInProcForIIS6.FlushCore(Byte[] status, Byte[] header, Int32 keepConnected, Int32 totalBodySize, Int32 numBodyFragments, IntPtr[] bodyFragments, Int32[] bodyFragmentLengths, Int32 doneWithSession, Int32 finalStatus, Boolean& async)
at System.Web.Hosting.ISAPIWorkerRequest.FlushCachedResponse(Boolean isFinal)
at System.Web.HttpResponse.Flush(Boolean finalFlush)
at System.Web.HttpResponse.BinaryWrite(Byte[] buffer)
at DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.WriteToResponse(String fileName, Boolean saveAsFile, String fileFormat, ExportToStream getStream, ExportOptionsBase options)
at DevExpress.Web.ASPxGridView.Export.ASPxGridViewExporter.WriteXlsToResponse(String fileName, Boolean saveAsFile)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.HandleError(Exception e)
at System.Web.UI.Page.ProcessRequestMain(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest(Boolean includeStagesBeforeAsyncPoint, Boolean includeStagesAfterAsyncPoint)
at System.Web.UI.Page.ProcessRequest()
at System.Web.UI.Page.ProcessRequest(HttpContext context)
at ASP.testB_aspx.ProcessRequest(HttpContext context)
at System.Web.HttpApplication.CallHandlerExecutionStep.System.Web.HttpApplication.IExecutionStep.Execute()
ASPxGridViewExporter.WriteXlsToResponse가 실행되는 동안 발생한 것으로, 0x800703E3 오류에 대해 검색해 보면,
Exception (Message): The remote host closed the connection. The error code is 0x800703E3
; https://stackoverflow.com/questions/22084835/exception-message-the-remote-host-closed-the-connection-the-error-code-is-0x
클라이언트 측, 즉 위의 경우에는 웹 브라우저의 사용자가 기다리다 못해 그냥 화면을 닫아버려 소켓 연결이 끊긴 것에 해당합니다. 아마도 사용자는 너무 오래 걸려서 이상하다고 판단해 다시 그 작업을 요청했을 것이고, 그 요청으로 인해 다시 CPU 사용량이 올라가는 악순환이 발생했을 것입니다.
[이 글에 대해서 여러분들과 의견을 공유하고 싶습니다. 틀리거나 미흡한 부분 또는 의문 사항이 있으시면 언제든 댓글 남겨주십시오.]