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

[Juan José Gil]

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

[Jeff Scott Brown]

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/

[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
colin.ha...@gmail.com

--
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 grails-dev-discuss+unsub...@googlegroups.com.
To post to this group, send email to grails-dev-discuss@googlegroups.com.
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.

[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
colin.ha...@gmail.com

On Wed, Apr 4, 2018 at 9:55 AM, Jeff Scott Brown <bro...@objectcomputing.com> 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 grails-dev-discuss+unsub...@googlegroups.com.

To post to this group, send email to grails-de...@googlegroups.com.