L'application à haut débit est déployée dans JBoss 7 qui traite plus de 200 000 requêtes par minute. L'application lit les requêtes http et les traite. La taille moyenne de la charge utile de la requête est de 1,5 Ko.SocketInputStream.socketRead0 occupe 30% du temps d'application
Un fil de cpu profileur montre ce qui suit:
55% du temps: Unsafe.park (threads en attente d'être affecté?)
30% du temps: SocketInputStream.socketRead0 (? Lecture probablement demandes de la prise)
8% Temps : code de l'application entière de traitement des demandes
4% du temps: code de printemps
quelqu'un peut-il jeter quelque lumière sur pourquoi pourrait beaucoup de temps est consacré à Unsafe.park et SocketInputStream.socketRead0? Comme pour les autres messages stackoverflow, Unsafe.park peut-être des threads en attente d'affectation, représentant la capacité de réserve (pas sûr de cela). Les 45% restants sont probablement la capacité réellement utilisée.
La partie la plus surprenante est que SocketInputStream.socketRead0 (cadres de pile de vidage de fil ci-dessous) occupe jusqu'à 30% du temps. Alors que le traitement des demandes, qui est l'ensemble du code de l'application complexe, y compris plusieurs recherches de réseau occupe seulement 8% du temps.
Si vous considérez seulement la capacité utilisée de 45%, SocketInputStream.socketRead0 prend 67% du temps.
La question principale est de savoir ce qui pourrait causer SocketInputStream.socketRead0 à prendre autant de temps? Tout pointeur aidera.
La décharge du fil présente les trames de traces à empilage suivantes pour 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
Stack cadres pour 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
trames Stack invoquer le code d'application:
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 (8 avril):
Eh bien, il semble que les cadres de la pile ci-dessus pour les 30% socketRead0 sont pour seulement lire la "ligne de demande", pas le corps de la demande. Voir ci-dessus
org.apache.coyote.http11.InternalInputBuffer.parseRequestLine() :369,368
Transforme le « corps de la demande » est en fait en cours de lecture à partir du code d'application de 8% et prend 1,7% (ce qui semble encore plus élevé qu'il devrait prendre) du temps total. Suite des cadres de pile au-dessus d'appeler du code d'application pour montrer corps de la requête en cours de lecture:
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
Les questions sont toujours les mêmes:
1. Pourquoi le temps de 30% consacré à socketRead0? 2. Pourquoi 55% dans Unsafe.park?