New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

ConsulCatalogWatch blocks scheduler thread #146

Closed
dvbobrov opened this Issue Feb 26, 2016 · 7 comments

Comments

Projects
4 participants
@dvbobrov

dvbobrov commented Feb 26, 2016

By default, Spring creates a single thread for all @Scheduled tasks (1). ConsulCatalogWatch uses blocking IO to watch for updates, causing all other tasks to wait until timeout expires. This is not an expected behavior, made worse by the fact that ConsulCatalogWatch is enabled by default.

@spencergibb

This comment has been minimized.

Show comment
Hide comment
@spencergibb

spencergibb Feb 26, 2016

Member

The obvious workarounds are to disable the watch, or change the spring.cloud.consul.config.watch.delay. You can also create a @Bean of type SchedulingConfigurer to configure things to your pleasure.

Member

spencergibb commented Feb 26, 2016

The obvious workarounds are to disable the watch, or change the spring.cloud.consul.config.watch.delay. You can also create a @Bean of type SchedulingConfigurer to configure things to your pleasure.

@dvbobrov

This comment has been minimized.

Show comment
Hide comment
@dvbobrov

dvbobrov Feb 26, 2016

@spencergibb yes, but my point was that default configuration may cause problems in code not related to Spring Cloud Consul. This should either be mentioned in documentation or fixed by using asynchronous IO.

dvbobrov commented Feb 26, 2016

@spencergibb yes, but my point was that default configuration may cause problems in code not related to Spring Cloud Consul. This should either be mentioned in documentation or fixed by using asynchronous IO.

@spencergibb

This comment has been minimized.

Show comment
Hide comment
@spencergibb

spencergibb Feb 26, 2016

Member

Explain "causing all other tasks to wait until timeout expires" a bit more.

Member

spencergibb commented Feb 26, 2016

Explain "causing all other tasks to wait until timeout expires" a bit more.

@dvbobrov

This comment has been minimized.

Show comment
Hide comment
@dvbobrov

dvbobrov Feb 26, 2016

When a watch task executes, it blocks a scheduler thread for catalog-services-watch-timeout (e.g. 30) seconds. During this time no other @Scheduled task can run.

dvbobrov commented Feb 26, 2016

When a watch task executes, it blocks a scheduler thread for catalog-services-watch-timeout (e.g. 30) seconds. During this time no other @Scheduled task can run.

@spencergibb

This comment has been minimized.

Show comment
Hide comment
@spencergibb

spencergibb Feb 26, 2016

Member

Thanks for the clarification.

Member

spencergibb commented Feb 26, 2016

Thanks for the clarification.

@jihor

This comment has been minimized.

Show comment
Hide comment
@jihor

jihor Aug 19, 2016

Contributor

@spencergibb I'd like to add that ConfigWatch.watchConfigKeyValues() is working quite long compared to ConsulCatalogWatch.catalogServicesWatch().
We've measured execution times for both methods using a simple @Around-aspect and were puzzled to see ConfigWatch.watchConfigKeyValues() executing around 8 sec while ConsulCatalogWatch.catalogServicesWatch() was taking mere milliseconds to execute. First execution of ConfigWatch.watchConfigKeyValues() was also fast for some reason.

Log excerpt:

16:49:26.161 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() started at Fri Aug 19 16:49:26 MSK 2016
16:49:26.204 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() finished at Fri Aug 19 16:49:26 MSK 2016; working time is 0.044 s
16:49:26.205 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:26 MSK 2016
16:49:26.230 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:26 MSK 2016; working time is 0.024 s
16:49:27.230 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:27 MSK 2016
16:49:35.568 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:35 MSK 2016; working time is 8.337 s
16:49:36.569 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:36 MSK 2016
16:49:44.869 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:44 MSK 2016; working time is 8.301 s
16:49:45.869 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:45 MSK 2016
16:49:54.205 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:54 MSK 2016; working time is 8.336 s
16:49:55.206 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:55 MSK 2016
16:50:03.489 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:03 MSK 2016; working time is 8.283 s
16:50:03.489 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() started at Fri Aug 19 16:50:03 MSK 2016
16:50:03.493 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() finished at Fri Aug 19 16:50:03 MSK 2016; working time is 0.003 s
16:50:04.489 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:04 MSK 2016
16:50:12.801 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:12 MSK 2016; working time is 8.312 s
16:50:13.802 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:13 MSK 2016
16:50:22.234 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:22 MSK 2016; working time is 8.432 s
16:50:23.234 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:23 MSK 2016
16:50:31.475 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:31 MSK 2016; working time is 8.241 s
16:50:32.476 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:32 MSK 2016
16:50:40.670 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:40 MSK 2016; working time is 8.194 s

Is this expected? Should we maybe open a new issue on that topic?

Contributor

jihor commented Aug 19, 2016

@spencergibb I'd like to add that ConfigWatch.watchConfigKeyValues() is working quite long compared to ConsulCatalogWatch.catalogServicesWatch().
We've measured execution times for both methods using a simple @Around-aspect and were puzzled to see ConfigWatch.watchConfigKeyValues() executing around 8 sec while ConsulCatalogWatch.catalogServicesWatch() was taking mere milliseconds to execute. First execution of ConfigWatch.watchConfigKeyValues() was also fast for some reason.

Log excerpt:

16:49:26.161 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() started at Fri Aug 19 16:49:26 MSK 2016
16:49:26.204 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() finished at Fri Aug 19 16:49:26 MSK 2016; working time is 0.044 s
16:49:26.205 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:26 MSK 2016
16:49:26.230 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:26 MSK 2016; working time is 0.024 s
16:49:27.230 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:27 MSK 2016
16:49:35.568 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:35 MSK 2016; working time is 8.337 s
16:49:36.569 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:36 MSK 2016
16:49:44.869 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:44 MSK 2016; working time is 8.301 s
16:49:45.869 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:45 MSK 2016
16:49:54.205 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:49:54 MSK 2016; working time is 8.336 s
16:49:55.206 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:49:55 MSK 2016
16:50:03.489 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:03 MSK 2016; working time is 8.283 s
16:50:03.489 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() started at Fri Aug 19 16:50:03 MSK 2016
16:50:03.493 [DEBUG] [TestEventLogger]     ConsulCatalogWatch.catalogServicesWatch() finished at Fri Aug 19 16:50:03 MSK 2016; working time is 0.003 s
16:50:04.489 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:04 MSK 2016
16:50:12.801 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:12 MSK 2016; working time is 8.312 s
16:50:13.802 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:13 MSK 2016
16:50:22.234 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:22 MSK 2016; working time is 8.432 s
16:50:23.234 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:23 MSK 2016
16:50:31.475 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:31 MSK 2016; working time is 8.241 s
16:50:32.476 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() started at Fri Aug 19 16:50:32 MSK 2016
16:50:40.670 [DEBUG] [TestEventLogger]     ConfigWatch.watchConfigKeyValues() finished at Fri Aug 19 16:50:40 MSK 2016; working time is 8.194 s

Is this expected? Should we maybe open a new issue on that topic?

@cykl

This comment has been minimized.

Show comment
Hide comment
@cykl

cykl Dec 7, 2017

@jihor ConfigWatch relies on Consul blocking queries. It asks to synchronously wait until a change is performed inside the specified kv prefix or until a maximum wait time is reached. ConfigWatch default config is to wait up to 55 seconds (and is scheduled to run every second). As the use of a blocking query is explicitly requested, I think it is expected.

@spencergibb Until Spring Boot comes by default with a TaskExecutor compatible with ConfigWatch exepectation, wouldn't it be better to run this task in a dedicated thread? Or to warn the user if the default mono-thread TaskExecutor is detected? Or to document this requirement? Or to provide a suitable TaskExecutor if none is defined by the app? Please correct me if I am wrong, but my understanding is that any spring-cloud-consul user who hasn't defined a compatible TaskExecutor, for unrelated needs, might get hurt.

cykl commented Dec 7, 2017

@jihor ConfigWatch relies on Consul blocking queries. It asks to synchronously wait until a change is performed inside the specified kv prefix or until a maximum wait time is reached. ConfigWatch default config is to wait up to 55 seconds (and is scheduled to run every second). As the use of a blocking query is explicitly requested, I think it is expected.

@spencergibb Until Spring Boot comes by default with a TaskExecutor compatible with ConfigWatch exepectation, wouldn't it be better to run this task in a dedicated thread? Or to warn the user if the default mono-thread TaskExecutor is detected? Or to document this requirement? Or to provide a suitable TaskExecutor if none is defined by the app? Please correct me if I am wrong, but my understanding is that any spring-cloud-consul user who hasn't defined a compatible TaskExecutor, for unrelated needs, might get hurt.

@spencergibb spencergibb added this to To do in Finchley.RELEASE via automation Jun 5, 2018

@spencergibb spencergibb added this to the 2.0.0.RELEASE milestone Jun 5, 2018

Finchley.RELEASE automation moved this from To do to Done Jun 5, 2018

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment