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)
12986정성태2/28/20221632.NET Framework: 1168. C# -IIncrementalGenerator를 적용한 Version 2 Source Generator 실습
12985정성태2/28/20221749.NET Framework: 1167. C# -Version 1 Source Generator 실습
12984정성태2/24/20221553.NET Framework: 1166. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 filtering_video.c 예제 포팅
12983정성태2/24/20221659.NET Framework: 1165. .NET Core/5+ 빌드 시 runtimeconfig.json에 설정을 반영하는 방법
12982정성태2/24/20221592.NET Framework: 1164. HTTP Error 500.31 - ANCM Failed to Find Native Dependencies
12981정성태2/23/20221548VC++: 154. C/C++ 언어의 문자열 Literal에 인덱스 적용하는 구문 [1]
12980정성태2/23/20221835.NET Framework: 1163. C# - 윈도우 환경에서 usleep을 호출하는 방법 [2]
12979정성태2/22/20222241.NET Framework: 1162. C# - 인텔 CPU의 P-Core와 E-Core를 구분하는 방법파일 다운로드1
12978정성태2/21/20221642.NET Framework: 1161. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 resampling_audio.c 예제 포팅
12977정성태2/21/20223345.NET Framework: 1160. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 qsv 디코딩
12976정성태2/21/20221972VS.NET IDE: 174. Visual C++ - "External Dependencies" 노드 비활성화하는 방법
12975정성태2/20/20222160.NET Framework: 1159. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 qsvdec.c 예제 포팅파일 다운로드1
12974정성태2/20/20222054.NET Framework: 1158. C# - SqlConnection의 최소 Pooling 수를 초과한 DB 연결은 언제 해제될까요?
12973정성태2/16/20222106개발 환경 구성: 639. ffmpeg.exe - Intel Quick Sync Video(qsv)를 이용한 인코딩 [3]
12972정성태2/16/20221836Windows: 200. Intel CPU의 내장 그래픽 GPU가 작업 관리자에 없다면? [4]
12971정성태2/15/20222981.NET Framework: 1157. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 muxing.c 예제 포팅 [7]파일 다운로드1
12970정성태2/15/20221904.NET Framework: 1156. C# - ffmpeg(FFmpeg.AutoGen): Bitmap으로부터 h264 형식의 파일로 쓰기 [1]파일 다운로드1
12969정성태2/14/20222078개발 환경 구성: 638. Visual Studio의 Connection Manager 기능(Remote SSH 관리)을 위한 명령행 도구 - 두 번째 이야기파일 다운로드1
12968정성태2/14/20221379오류 유형: 794. msbuild 에러 - error NETSDK1005: Assets file '...\project.assets.json' doesn't have a target for '...'.
12967정성태2/14/20221662VC++: 153. Visual C++ - C99 표준의 Compund Literals 빌드 방법 [4]
12966정성태2/13/20221540.NET Framework: 1155. C# - ffmpeg(FFmpeg.AutoGen): Bitmap으로부터 yuv420p + rawvideo 형식의 파일로 쓰기파일 다운로드1
12965정성태2/13/20221647.NET Framework: 1154. "Hanja Hangul Project v1.01 (파이썬)"의 C# 버전
12964정성태2/11/20221585.NET Framework: 1153. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 avio_reading.c 예제 포팅파일 다운로드1
12963정성태2/11/20221739.NET Framework: 1152. C# - 화면 캡처한 이미지를 ffmpeg(FFmpeg.AutoGen)로 동영상 처리 (저해상도 현상 해결)파일 다운로드1
12962정성태2/9/20221461오류 유형: 793. 마이크로소프트 스토어 - 제품이 존재하지 않습니다. 재고가 없는 것일 수 있습니다.
12961정성태2/8/20221790.NET Framework: 1151. C# - ffmpeg(FFmpeg.AutoGen)를 이용한 비디오 프레임의 크기 및 포맷 변경 예제(scaling_video.c) [7]파일 다운로드1
1  2  3  4  5  6  7  8  [9]  10  11  12  13  14  15  ...