高吞吐量應用程序部署在JBoss 7中,每分鐘處理超過200k個請求。該應用程序讀取http請求並處理它們。平均請求有效負載大小爲1.5Kb。SocketInputStream.socketRead0佔用應用程序時間的30%
甲CPU線程探查顯示以下內容:
55%時間:Unsafe.park
(線程等待分配?)
30%的時間:SocketInputStream.socketRead0
(?大概讀取請求關閉插座)
8%時間:處理整個應用程序代碼請求
4%時間:春季碼
能有人扔爲什麼那麼多時間的威力在Unsafe.park
和SocketInputStream.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
?