Http11Processor taking too much time to init

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
5 messages Options
Reply | Threaded
Open this post in threaded view
|

Http11Processor taking too much time to init

Juan José Gil
Hi,

we have noted that grails controllers (and only the controllers) are consuming too much time to init the  first time they are accessed.
After fine tunning loggers and debugging we've find out that part of the problem *seems* to be related to some kind of Http11 NIO configuration. This is what logs are stating:

2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.g.w.s.m.GrailsWebRequestFilter         : Cleared Grails thread-bound request context: org.apache.catalina.connector.RequestFacade@33180f76
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.s.b.w.f.OrderedRequestContextFilter    : Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@33180f76
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.a.c.h.Http11Processor                  : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@489b6e83:org.apache.tomcat.util.net.NioChannel@59efb21a:java.nio.channels.SocketChannel[connected local=/127.0.0.1:8080 remote=/127.0.0.1:35074]], Status in: [OPEN_READ], State out: [OPEN]
***
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.a.c.h.Http11NioProtocol                : Pushed Processor [org.apache.coyote.http11.Http11Processor@723b8aa8]
***
2018-04-03 10:10:13.247 DEBUG --- [     http-nio-8080-exec-4] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-04-03 10:10:13.247 DEBUG --- [     http-nio-8080-exec-4] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'shiroAttributeSourceAdvisor'

as you can see, pushing the Http11Processor is taking 2s, and this is for every "first" controller access.
Can someone tell me if this is the expected behavior or what should I check to look for some missconfig or a hint to improve this times, it would be awesome.

This is our env environment,
$ grails -v
| Grails Version: 3.3.3
| Groovy Version: 2.4.14
| JVM Version: 1.8.0_152

The pc where I'm having this logs has an Intel Core i7-8700K Coffee Lake 6-Core 3.7 GHz (4.7 GHz Turbo) + GIGABYTE Z370XP SLI + 32GB DDR4 2400Mhz

Regards,
Juanjo

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/6b5d0b65-727e-4d24-9ec5-93b1c8814439%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Http11Processor taking too much time to init

Juan José Gil
sorry, I was thinking that this was the grails user ML.

On Tuesday, April 3, 2018 at 10:34:03 AM UTC-3, Juan José Gil wrote:
Hi,

we have noted that grails controllers (and only the controllers) are consuming too much time to init the  first time they are accessed.
After fine tunning loggers and debugging we've find out that part of the problem *seems* to be related to some kind of Http11 NIO configuration. This is what logs are stating:

2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.g.w.s.m.GrailsWebRequestFilter         : Cleared Grails thread-bound request context: org.apache.catalina.connector.RequestFacade@33180f76
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.s.b.w.f.OrderedRequestContextFilter    : Cleared thread-bound request context: org.apache.catalina.connector.RequestFacade@33180f76
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.a.c.h.Http11Processor                  : Socket: [org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper@489b6e83:org.apache.tomcat.util.net.NioChannel@59efb21a:java.nio.channels.SocketChannel[connected local=/<a href="http://127.0.0.1:8080" target="_blank" rel="nofollow" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2F127.0.0.1%3A8080\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGjBsLieL8l-6V0lF6rStXOlXcB0A&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2F127.0.0.1%3A8080\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNGjBsLieL8l-6V0lF6rStXOlXcB0A&#39;;return true;">127.0.0.1:8080 remote=/127.0.0.1:35074]], Status in: [OPEN_READ], State out: [OPEN]
***
2018-04-03 10:10:11.085 DEBUG --- [     http-nio-8080-exec-2] o.a.c.h.Http11NioProtocol                : Pushed Processor [org.apache.coyote.http11.Http11Processor@723b8aa8]
***
2018-04-03 10:10:13.247 DEBUG --- [     http-nio-8080-exec-4] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'org.springframework.transaction.config.internalTransactionAdvisor'
2018-04-03 10:10:13.247 DEBUG --- [     http-nio-8080-exec-4] o.s.b.f.s.DefaultListableBeanFactory     : Returning cached instance of singleton bean 'shiroAttributeSourceAdvisor'

as you can see, pushing the Http11Processor is taking 2s, and this is for every "first" controller access.
Can someone tell me if this is the expected behavior or what should I check to look for some missconfig or a hint to improve this times, it would be awesome.

This is our env environment,
$ grails -v
| Grails Version: 3.3.3
| Groovy Version: 2.4.14
| JVM Version: 1.8.0_152

The pc where I'm having this logs has an Intel Core i7-8700K Coffee Lake 6-Core 3.7 GHz (4.7 GHz Turbo) + GIGABYTE Z370XP SLI + 32GB DDR4 2400Mhz

Regards,
Juanjo

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/896d4fc6-e5f3-4e08-9614-3de3d401a6c9%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Http11Processor taking too much time to init

Jeff Scott Brown-4
On 3 Apr 2018, at 13:11, Juan José Gil wrote:

> sorry, I was thinking that this was the grails user ML.
>

It is.




JSB

--
Jeff Scott Brown
OCI Partner and Principal Software Engineer
OCI Grails Practice Lead

Autism Strikes 1 in 166
Find The Cause ~ Find The Cure
http://www.autismspeaks.org/

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com.
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Http11Processor taking too much time to init

Colin Harrington
Juanjo, 

I'm not sure that your issue is Tomcat's Http11Processor.  It might be a bit misleading since every HTTP/1.1 request goes through the Http11Processor.  It might be worth bumping up the rest of your logging to diagnose what else might be delaying after the Pushed Processor [org.apache.coyote.http11.Http11Processor@723b8aa8] message but before the DefaultListableBeanFactory messages.

I don't see a 2s delay on a default Grails 3.3.3 app on similar hardware and I would not expect a 2s delay before the first request without some solid justification.  

Colin Harrington
[hidden email]

On Wed, Apr 4, 2018 at 9:55 AM, Jeff Scott Brown <[hidden email]> wrote:
On 3 Apr 2018, at 13:11, Juan José Gil wrote:

> sorry, I was thinking that this was the grails user ML.
>

It is.




JSB

--
Jeff Scott Brown
OCI Partner and Principal Software Engineer
OCI Grails Practice Lead

Autism Strikes 1 in 166
Find The Cause ~ Find The Cure
http://www.autismspeaks.org/

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com.
For more options, visit https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/CAJPZsWL4BqvwKo_dzWeqSaRTWrUE_9uiALrMrA0Y1OX0zaDtuQ%40mail.gmail.com.
For more options, visit https://groups.google.com/d/optout.
Reply | Threaded
Open this post in threaded view
|

Re: Http11Processor taking too much time to init

Juan José Gil
Thanks Colin,

The logs are at TRACE level, so I can't get anything more from them :/
The problem is repeating for each controller, the first time accessed.

I'm thinking to create a WAR and see if the problem is reproducible in a standalone tomcat, I don't remember where, but today I saw some reports stating problems with okio and okhttp libs.


On Friday, April 6, 2018 at 4:59:50 PM UTC-3, Colin Harrington wrote:
Juanjo, 

I'm not sure that your issue is Tomcat's Http11Processor.  It might be a bit misleading since every HTTP/1.1 request goes through the Http11Processor.  It might be worth bumping up the rest of your logging to diagnose what else might be delaying after the Pushed Processor [org.apache.coyote.http11.Http11Processor@723b8aa8] message but before the DefaultListableBeanFactory messages.

I don't see a 2s delay on a default Grails 3.3.3 app on similar hardware and I would not expect a 2s delay before the first request without some solid justification.  

Colin Harrington
<a href="javascript:" target="_blank" gdf-obfuscated-mailto="IwIRYpY4CAAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">colin.ha...@...

On Wed, Apr 4, 2018 at 9:55 AM, Jeff Scott Brown <<a href="javascript:" target="_blank" gdf-obfuscated-mailto="IwIRYpY4CAAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">bro...@...> wrote:
On 3 Apr 2018, at 13:11, Juan José Gil wrote:

> sorry, I was thinking that this was the grails user ML.
>

It is.




JSB

--
Jeff Scott Brown
OCI Partner and Principal Software Engineer
OCI Grails Practice Lead

Autism Strikes 1 in 166
Find The Cause ~ Find The Cure
<a href="http://www.autismspeaks.org/" rel="nofollow" target="_blank" onmousedown="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fwww.autismspeaks.org%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHLOilSQBYB1lzLN6Ms6K6DtQY5DQ&#39;;return true;" onclick="this.href=&#39;http://www.google.com/url?q\x3dhttp%3A%2F%2Fwww.autismspeaks.org%2F\x26sa\x3dD\x26sntz\x3d1\x26usg\x3dAFQjCNHLOilSQBYB1lzLN6Ms6K6DtQY5DQ&#39;;return true;">http://www.autismspeaks.org/

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="IwIRYpY4CAAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">grails-dev-discuss+unsubscribe@....
To post to this group, send email to <a href="javascript:" target="_blank" gdf-obfuscated-mailto="IwIRYpY4CAAJ" rel="nofollow" onmousedown="this.href=&#39;javascript:&#39;;return true;" onclick="this.href=&#39;javascript:&#39;;return true;">grails-de...@googlegroups.com.
To view this discussion on the web visit <a href="https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com&#39;;return true;">https://groups.google.com/d/msgid/grails-dev-discuss/67D9821E-DE6B-4E11-9BCF-92833C05172A%40objectcomputing.com.
For more options, visit <a href="https://groups.google.com/d/optout" rel="nofollow" target="_blank" onmousedown="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;" onclick="this.href=&#39;https://groups.google.com/d/optout&#39;;return true;">https://groups.google.com/d/optout.

--
You received this message because you are subscribed to the Google Groups "Grails Dev Discuss" group.
To unsubscribe from this group and stop receiving emails from it, send an email to [hidden email].
To post to this group, send email to [hidden email].
To view this discussion on the web visit https://groups.google.com/d/msgid/grails-dev-discuss/a0158273-0fe1-4cd9-bcf3-efd4d24b3e02%40googlegroups.com.
For more options, visit https://groups.google.com/d/optout.