Startup very slow with many controllers due to "x message handler methods found" check

[dularion]

We have a grails 3.2.9 application using v2.3.0 of grails-spring-websocket and with many controllers we are experiencing very slow startup time. With debug enabled we see this

2017-05-17 09:32:25.866 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class kcenter.DmtController: {}
2017-05-17 09:32:26.023 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class systaro.ui.UisExampleController: {}
2017-05-17 09:32:26.230 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class kcenter.TecartTestController: {}
2017-05-17 09:32:27.325 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class kcenter.ProductGroupController: {}

and as you can see with the timestamps it almost takes 1 second for each controller to return "0 message handler methods found", and with 40+ controllers this adds tremendous time on the startup for each one of our developers, decreasing motivation all around.

This debug message comes internally from spring-messaging-4.3.8.RELEASE-sources.jar!/org/springframework/messaging/handler/invocation/AbstractMethodMessageHandler.java:243. I Wasn't sure where to ask this question, but I wanted to try here first.

Thanks in advance for any support!

[zyro23]

tried to reproduce that performance issue.. no luck :/ check referenced sample app. stock grails-3.2.9 app, readme example and additional 20 controllers. startup debug logs:

2017-05-17 10:33:25.243 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy16Controller: {}
2017-05-17 10:33:25.271 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy7Controller: {}
2017-05-17 10:33:25.303 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 1 message handler methods found on class myapp.ExampleController: {protected java.lang.String myapp.ExampleController.hello(java.lang.String)={[/hello],messageType=[MESSAGE]}}
2017-05-17 10:33:25.304  INFO --- [           main] GrailsSimpAnnotationMethodMessageHandler : Mapped "{[/hello],messageType=[MESSAGE]}" onto protected java.lang.String myapp.ExampleController.hello(java.lang.String)
2017-05-17 10:33:25.332 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy8Controller: {}
2017-05-17 10:33:25.369 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy15Controller: {}
2017-05-17 10:33:25.400 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy14Controller: {}
2017-05-17 10:33:25.432 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy9Controller: {}
2017-05-17 10:33:25.463 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy17Controller: {}
2017-05-17 10:33:25.494 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy6Controller: {}
2017-05-17 10:33:25.526 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy20Controller: {}
2017-05-17 10:33:25.556 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy3Controller: {}
2017-05-17 10:33:25.589 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy12Controller: {}
2017-05-17 10:33:25.624 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy19Controller: {}
2017-05-17 10:33:25.654 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy2Controller: {}
2017-05-17 10:33:25.684 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy11Controller: {}
2017-05-17 10:33:25.713 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy4Controller: {}
2017-05-17 10:33:25.742 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy18Controller: {}
2017-05-17 10:33:25.773 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy1Controller: {}
2017-05-17 10:33:25.801 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.DummyController: {}
2017-05-17 10:33:25.831 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy5Controller: {}
2017-05-17 10:33:25.861 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy13Controller: {}
2017-05-17 10:33:25.891 DEBUG --- [           main] GrailsSimpAnnotationMethodMessageHandler : 0 message handler methods found on class myapp.Dummy10Controller: {}

that looks more like 30milliseconds per controller class scanned, not 1 second.

please reference a sample app actually reproducing the problem.

[dularion]

Thank you, we will try to reproduce from stock and supply the app when we can reproduce it

[dularion]

Hm, So we did two things:

1. we started with a stock grails and added and added and added stuff incrementally from our main application to see when the startup time starts to explode, but after a lot of time we still couldn't reproduce, so we were a bit stumped
2. on a separate branch of our main application we stripped away and stripped away and stripped away so much stuff from our main application, but the startup time was still horrible.

So now we are kind of stumped. We are kind of concluding that its the fact that we have 50 domains, 60 controllers, 70 services, and just a bunch of code. Have you guys ever experienced this? Is this a common issue with large apps that startup time increases this dramatically with application size?

[zyro23]

nope, not seen this yet... but im still not sure that your conclusion that "it almost takes 1 second for each controller to return [...]" is correct. all beans are scanned but the debug log is only printed for controllers (because they are actual candidates to scan their methods). also, are you sure there is nothing running in parallel inside the app at the time of initialization (maybe other threads crunching something)?

tbh, not yet convinced that the spring-websocket handler scan is really the cause for the behavior you are seeing.

[zyro23]

any news on this one? did you find the cause of the slowdown?

[dularion]

Hi, Thanks for asking. I've come to agree with your previous statement that it is probably not the spring-websocket handler that is the cause, the logs are just a symptom of something else. We have not yet been able to replicate the behaviour by building onto vanilla, so we will see what happens when we strip the application down, which we soon have to do anyway for another project. but until then it is best to close this issue, for your peace of mind :D thanks for your awesome support!