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

제니퍼 닷넷 적용 사례 (8) - CPU high와 DB 쿼리 성능에 문제가 함께 있는 사이트

한 고객사의 X-View 화면입니다.

net_dev_express_cpu_high_0.png

새벽 시간을 지나, 업무 시간이 되면서 수백 초의 응답시간을 갖는 점들로 가득한 상태입니다. 당연히 고객사는 원인을 밝히고 싶어 했는데요. (그런데... 정말 개인적인 의문인데, 저런 상황에서는 이성적인 개발자라면 조금만 살펴봐도 원인이 나오지 않을까요? ^^) 문제가 되는 페이지는 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 상세 보기 화면에서 확인할 수 있는데요,

net_dev_express_cpu_high_1.png

보는 바와 같이 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 사용량이 올라가는 악순환이 발생했을 것입니다.




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







[최초 등록일: ]
[최종 수정일: 1/10/2022]

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

비밀번호

댓글 작성자
 




[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...
NoWriterDateCnt.TitleFile(s)
13064정성태5/18/202252.NET Framework: 2016. C# - JIT 컴파일러의 인라인 메서드 처리 유무
13063정성태5/18/202287.NET Framework: 2015. C# - 인라인 메서드(inline methods)
13062정성태5/17/2022217.NET Framework: 2014. C# - async/await 그리고 스레드 (4) 비동기 I/O 재현파일 다운로드1
13061정성태5/16/202270.NET Framework: 2013. C# - FILE_FLAG_OVERLAPPED가 적용된 파일의 읽기/쓰기 시 Position 관리파일 다운로드1
13060정성태5/15/2022146.NET Framework: 2012. C# - async/await 그리고 스레드 (3) Task.Delay 재현파일 다운로드1
13059정성태5/14/2022145.NET Framework: 2011. C# - CLR ThreadPool의 I/O 스레드에 작업을 맡기는 방법파일 다운로드1
13058정성태5/13/202289.NET Framework: 2010. C# - ThreadPool.SetMaxThreads 사용법
13057정성태5/12/202254오류 유형: 812. 파이썬 - ImportError: cannot import name ...
13056정성태5/12/2022256.NET Framework: 2009. C# - async/await 그리고 스레드 (2) MyTask의 호출 흐름 [2]파일 다운로드1
13055정성태5/11/2022358.NET Framework: 2008. C# - async/await 그리고 스레드 (1) MyTask로 재현 [4]파일 다운로드1
13054정성태5/11/2022224.NET Framework: 2007. C# - 10진수 숫자를 담은 문자열을 숫자로 변환하는 방법 [9]파일 다운로드1
13053정성태5/10/2022103.NET Framework: 2006. C# - GC.KeepAlive 메서드의 역할
13052정성태5/9/2022174.NET Framework: 2005. C# - 생성한 참조 개체가 언제 GC의 정리 대상이 될까요?
13051정성태5/8/202298.NET Framework: 2004. C# XingAPI - ACF 검색 결과로 구한 CSV 파일을 통해 퀀트 종목 찾기파일 다운로드1
13050정성태5/6/202295.NET Framework: 2003. C# - COM 개체의 이벤트 핸들러에서 발생하는 예외에 대한 CLR의 특별 대우파일 다운로드1
13049정성태5/6/202248오류 유형: 811. GoLand - Error: Cannot find package
13048정성태5/6/202257오류 유형: 810. "ASUS TUF GAMING B550M-PLUS (WI-FI)" 모델에서 블루투스 장치가 인식이 안 되는 문제
13047정성태5/6/202246오류 유형: 809. Speech Recognition could not start
13046정성태5/5/202297.NET Framework: 2002. C# XingAPI - ACF 파일을 이용한 퀀트 종목 찾기(t1857)
13045정성태5/5/202290.NET Framework: 2001. C# XingAPI - 주식 종목에 따른 PBR, PER, ROE 구하는 방법(t3341 예제)
13044정성태5/4/202252오류 유형: 808. error : clang++ exited with code 127
13043정성태5/3/202261오류 유형: 807. C# - 닷넷 응용 프로그램에서 Informix DB 사용 시 오류 메시지 정리
13042정성태5/3/2022142.NET Framework: 2000. C# - 닷넷 응용 프로그램에서 Informix DB 사용 방법파일 다운로드1
13041정성태4/28/202283개발 환경 구성: 642. Informix 데이터베이스 docker 환경 구성
13040정성태4/27/202286VC++: 156. 비주얼 스튜디오 - Linux C/C++ 프로젝트에서 openssl 링크하는 방법
[1]  2  3  4  5  6  7  8  9  10  11  12  13  14  15  ...