2017-04-08 14 views
1

高吞吐量應用程序部署在JBoss 7中,每分鐘處理超過200k個請求。該應用程序讀取http請求並處理它們。平均請求有效負載大小爲1.5Kb。SocketInputStream.socketRead0佔用應用程序時間的30%

甲CPU線程探查顯示以下內容:

55%時間:Unsafe.park(線程等待分配?)
30%的時間:SocketInputStream.socketRead0(?大概讀取請求關閉插座)
8%時間:處理整個應用程序代碼請求
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$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 

堆棧幀調用的應用程序代碼:

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( 4月8日):
好吧,看起來30%socketRead0的上述堆棧幀僅用於讀取「請求行」,而不是請求主體。見上面

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

打開了「請求主體」實際上是被從8%的應用程序代碼讀出,並正在採取1.7%(這似乎仍然比它應該承擔更高)的總時間。調用的應用程序代碼,以顯示請求體以上的堆棧幀的延續被讀取:

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 

問題是仍然是相同的:
1.爲什麼30%的時間中花費socketRead0? 2.爲什麼55%在Unsafe.park

回答

0

這已解決。按照Thread Profiler documentation

探查器結束運行後,代理將報告配置文件數據。調用樹會自動出現在Thread Profiler頁面上。調用樹中的百分比表示每個調用路徑在分析會話期間出現的線程回溯樣本的百分比。

New Relic線程分析器通過抽樣工作。百分比不是花費的時間,而只是方法出現的樣本的百分比。

交易是顯示哪些方法是最耗時的功能。 Doc here

相關問題