2017-04-08 1 views
1

분당 200,000 개 이상의 요청을 처리하는 JBoss 7에 처리량이 높은 응용 프로그램이 배포되었습니다. 응용 프로그램은 http 요청을 읽고 처리합니다. 평균 요청 페이로드 크기는 1.5Kb입니다.SocketInputStream.socketRead0은 응용 프로그램 시간의 30 %를 차지합니다.

55 % 시간 : Unsafe.park (스레드가 할당 기다리고?)
30 % 시간 : SocketInputStream.socketRead0 (? 아마 소켓 해제 요청을 읽기)
8 % 시간

는 CPU 스레드 프로파일 러

는 다음을 보여줍니다 : 처리를 위해 전체 응용 프로그램 코드는
4 %의 시간을 요청 봄 코드

사람이 너무 많은 시간의 힘이 Unsafe.parkSocketInputStream.socketRead0에 소요되는 이유에 대한 몇 가지 빛을 던질 수 있습니까? 다른 stackoverflow 게시물에 따라, Unsafe.park은 할당 대기중인 스레드 (예약 용량을 나타냄) (확실하지 않음). 나머지 45 %는 실제 사용 된 용량 일 것입니다.

가장 놀라운 부분은 SocketInputStream.socketRead0 (아래의 스레드 덤프 스택 프레임)이 30 %의 시간을 차지한다는 것입니다. 여러 네트워크 조회를 포함하여 복잡한 응용 프로그램 코드 전체를 처리하는 요청은 시간의 8 % 만 차지합니다.

사용량이 45 %라고 가정하면 SocketInputStream.socketRead0에 67 %의 시간이 걸립니다.

주된 질문은 SocketInputStream.socketRead0에 너무 많은 시간이 걸릴 수 있습니다. 모든 포인터가 도움이 될 것입니다.

스레드 덤프 SocketInputStream.socketRead0

org.jboss.threads.JBossThread.run() :122 
java.lang.Thread.run() :745 
org.jboss.threads.QueueExecutor$Worker.run() :835,825,840,842 
org.jboss.threads.QueueExecutor.access$100(org.jboss.threads.QueueExecutor, java.lang.Runnable) :45 
org.jboss.threads.QueueExecutor.runTask(java.lang.Runnable) :801 
org.jboss.threads.SimpleDirectExecutor.execute(java.lang.Runnable) :33 
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run() :520,518 
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(java.net.Socket) :671 
org.apache.coyote.http11.Http11Processor.process(java.net.Socket) :838,877,904,844 
org.apache.coyote.http11.InternalInputBuffer.parseRequestLine() :369,368 
org.apache.coyote.http11.InternalInputBuffer.fill() :731 
java.net.SocketInputStream.read(byte[], int, int) :122 
java.net.SocketInputStream.read(byte[], int, int, int) :152 
java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) :native 

스택에 대해 다음 스택 추적 프레임을 보여준다는 Unsafe.park을위한 프레임 :

org.jboss.threads.JBossThread.run() :122 
java.lang.Thread.run() :745 
org.jboss.threads.QueueExecutor$Worker.run() :835,825,840,842 
org.jboss.threads.QueueExecutor.access$100(org.jboss.threads.QueueExecutor, java.lang.Runnable) :45 
org.jboss.threads.QueueExecutor.runTask(java.lang.Runnable) :801 
org.jboss.threads.SimpleDirectExecutor.execute(java.lang.Runnable) :33 
org.apache.tomcat.util.net.JIoEndpoint$SocketProcessor.run() :520,518 
org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(java.net.Socket) :671 
org.apache.coyote.http11.Http11Processor.process(java.net.Socket) :838,877,904,844 
org.apache.catalina.connector.CoyoteAdapter.service(org.apache.coyote.Request, org.apache.coyote.Response) :395,368,364,365 
org.apache.catalina.core.StandardEngineValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :109 
org.apache.catalina.valves.ErrorReportValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :123,131,102 
org.apache.catalina.core.StandardHostValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :125,143,185,155 
org.jboss.as.web.security.SecurityContextAssociationValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :159,155,93,153,72,86,158,92,83,109 
org.jboss.as.jpa.interceptor.WebNonTxEmCloserValve.invoke :50,47 
org.apache.catalina.core.StandardContextValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :161 
org.apache.catalina.core.StandardWrapperValve.invoke(org.apache.catalina.connector.Request, org.apache.catalina.connector.Response) :283,253,275 
org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) :248 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) :280 
org.springframework.web.filter.OncePerRequestFilter.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse, javax.servlet.FilterChain) :76,74,-1,67,83 
org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, javax.servlet.FilterChain) :88 
org.apache.catalina.core.ApplicationFilterChain.doFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) :248 
org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(javax.servlet.ServletRequest, javax.servlet.ServletResponse) :329 
javax.servlet.http.HttpServlet.service(javax.servlet.ServletRequest, javax.servlet.ServletResponse) :848,-1,847 
javax.servlet.http.HttpServlet.service(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) :754,781 
org.springframework.web.servlet.FrameworkServlet.doPost(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) :789 
org.springframework.web.servlet.FrameworkServlet.processRequest(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) :867,920,873,882,866,919,870 
org.springframework.web.servlet.DispatcherServlet.doService(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) :842,848,840,849,839,852,841 
org.springframework.web.servlet.DispatcherServlet.doDispatch(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse) :886,934,923,963,893,910,-1,984,914 
org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, java.lang.Object) :80,-1 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.springframework.web.method.HandlerMethod) :578 
org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, org.springframework.web.method.HandlerMethod) :621,610,606,-1,609,608,617,612,614,618 
org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(org.springframework.web.context.request.NativeWebRequest, org.springframework.web.method.support.ModelAndViewContainer, java.lang.Object[]) :96 
org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(org.springframework.web.context.request.NativeWebRequest, org.springframework.web.method.support.ModelAndViewContainer, java.lang.Object[]) :126,117 
org.springframework.web.method.support.InvocableHandlerMethod.invoke(java.lang.Object[]) :213 
java.lang.reflect.Method.invoke(java.lang.Object, java.lang.Object[]) :606 
sun.reflect.DelegatingMethodAccessorImpl.invoke(java.lang.Object, java.lang.Object[]) :43 
sun.reflect.GeneratedMethodAccessor405.invoke(java.lang.Object, java.lang.Object[]) 
com.myco.myapp.AppController.process(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, java.io.Writer, @RequestHeader java.lang.String, @PathVariable java.lang.String, @RequestParam java.lang.String) :84,83,82 

EDIT (:

org.jboss.threads.JBossThread.run() :122 
java.lang.Thread.run() :745 
org.jboss.threads.QueueExecutor$Worker.run() :835,825,840,842 
org.jboss.threads.QueueExecutor.access$400(org.jboss.threads.QueueExecutor) :45 
org.jboss.threads.QueueExecutor.takeTask() :746 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await() :2039,2043 
java.util.concurrent.locks.LockSupport.park(java.lang.Object) :186 
sun.misc.Unsafe.park(boolean, long) :native 

스택 호출하는 응용 프로그램 코드를 프레임 Apr 8) :
30 % socketRead0에 대한 위의 스택 프레임은 요청 본문이 아닌 "요청 라인"만을 읽는 것입니다.

org.apache.coyote.http11.InternalInputBuffer.parseRequestLine() :369,368 

는 "요청 본문은"실제로 8 %의 응용 프로그램 코드에서 읽을되고 있으며 전체 시간의 (아직도해야보다 높은 것) 1.7 %를 복용 밝혀 위를 참조하십시오. 요청 본문을 표시하는 응용 프로그램 코드를 호출하는 위의 스택 프레임의 연속 읽기되고 :
1. 30 %의 시간이 socketRead0에서 보낸 이유 :

com.myco.myapp.AppController.process(javax.servlet.http.HttpServletRequest, javax.servlet.http.HttpServletResponse, java.io.Writer, @RequestHeader java.lang.String, @PathVariable java.lang.String, @RequestParam java.lang.String) :84,83,82 
com.myco.myapp.AppController.getRequestBody(javax.servlet.http.HttpServletRequest, java.lang.String) :229,221,222,-1 
org.apache.catalina.connector.CoyoteReader.readLine() :190,203,158,201,192,204 
org.apache.catalina.connector.CoyoteReader.read(char[], int, int) :105 
org.apache.catalina.connector.InputBuffer.read(char[], int, int) :447 
org.apache.tomcat.util.buf.CharChunk.substract(char[], int, int) :445 
org.apache.catalina.connector.InputBuffer.realReadChars(char[], int, int) :398 
org.apache.catalina.connector.InputBuffer.realReadBytes(byte[], int, int) :347 
org.apache.coyote.Request.doRead(org.apache.tomcat.util.buf.ByteChunk) :438 
org.apache.coyote.http11.InternalInputBuffer.doRead(org.apache.tomcat.util.buf.ByteChunk, org.apache.coyote.Request) :706 
org.apache.coyote.http11.filters.IdentityInputFilter.doRead(org.apache.tomcat.util.buf.ByteChunk, org.apache.coyote.Request) :116 
org.apache.coyote.http11.InternalInputBuffer$InputStreamInputBuffer.doRead(org.apache.tomcat.util.buf.ByteChunk, org.apache.coyote.Request) :777 
org.apache.coyote.http11.InternalInputBuffer.fill() :747 
java.net.SocketInputStream.read(multiple parameter matches) :-1,122 
java.net.SocketInputStream.read(byte[], int, int, int) :152 
java.net.SocketInputStream.socketRead0(java.io.FileDescriptor, byte[], int, int, int) :native 

질문은 여전히 ​​동일하다? Unsafe.park에서 55 %를 왜 사용해야하나요?

답변

0

이 문제가 해결되었습니다. Thread Profiler documentation에 따라 :

프로필러 실행이 끝나면 에이전트는 프로필 데이터를보고합니다.스레드 트리는 자동으로 스레드 프로파일 러 페이지에 나타납니다. 호출 트리의 백분율은 프로파일 링 세션 중에 각 호출 경로가 표시된 스레드 백 트레이스 샘플의 백분율을 나타냅니다.

새로운 유물 스레드 프로파일 러는 샘플링을 통해 작동합니다. 백분율은 소비 된 시간이 아니며 단순히 방법이 나타난 샘플의 비율입니다.

트랜잭션은 가장 시간이 많이 걸리는 메서드를 나타내는 함수입니다. 문서 here

관련 문제