Task rejected from pool even when queue is configured

[andersdavoust]

Hello,

I have configured a thread pool like this:

super(Setter.withGroupKey(HystrixCommandGroupKey.Factory.asKey(GROUP_KEY))
              .andCommandKey(HystrixCommandKey.Factory.asKey(COMMAND_KEY))
              .andCommandPropertiesDefaults(
                      HystrixCommandProperties.Setter().withExecutionTimeoutInMilliseconds(6000))
              .andThreadPoolPropertiesDefaults(
                      HystrixThreadPoolProperties.Setter()
                              .withMaxQueueSize(100)
                              .withQueueSizeRejectionThreshold(100)
                              .withCoreSize(10)));

As long as there is a thread available in the pool I want the task to be performed and if there are no threads available I want the task to be added to a queue and be performed when a thread becomes available.

When performing jobs with more than 10 task I keep getting the following exception:

2016-11-23 07:31:38.039 ERROR 1 --- [io-8080-exec-10] s.p.c.i.c.p.SomeService : Timeout or error occurred so fallback was called when calling...
java.util.concurrent.RejectedExecutionException: Task java.util.concurrent.FutureTask@44979ab rejected from java.util.concurrent.ThreadPoolExecutor@3770d3f6[Running, pool size = 10, active threads = 10, queued tasks = 0, completed tasks = 10]
at java.util.concurrent.ThreadPoolExecutor$AbortPolicy.rejectedExecution(ThreadPoolExecutor.java:2047) ~[na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.reject(ThreadPoolExecutor.java:823) [na:1.8.0_92]
at java.util.concurrent.ThreadPoolExecutor.execute(ThreadPoolExecutor.java:1369) [na:1.8.0_92]
at java.util.concurrent.AbstractExecutorService.submit(AbstractExecutorService.java:112) ~[na:1.8.0_92]
at com.netflix.hystrix.strategy.concurrency.HystrixContextScheduler$ThreadPoolWorker.schedule(HystrixContextScheduler.java:172) ~[hystrix-core-1.5.8.jar!/:1.5.8]
at com.netflix.hystrix.strategy.concurrency.HystrixContextScheduler$HystrixContextSchedulerWorker.schedule(HystrixContextScheduler.java:106) ~[hystrix-core-1.5.8.jar!/:1.5.8]
at rx.internal.operators.OperatorSubscribeOn.call(OperatorSubscribeOn.java:45) ~[rxjava-1.1.5.jar!/:1.1.5]
at rx.internal.operators.OperatorSubscribeOn.call(OperatorSubscribeOn.java:30) ~[rxjava-1.1.5.jar!/:1.1.5]

Shouldn't the task be put on the queue? According to the exception queued tasks is 0. I would understand this behavior if queued tasks were 100.

[mattrjacobs]

The way it actually works (j.u.c.ThreadPoolExecutor) is that all work submitted goes into the queue first. Then the thread pool picks up tasks as it is able to.

Still, in your case, I would expect that tasks would end up in the queue. Do you have a unit test that reproduces this behavior?

[andersdavoust]

Thanks for the clarification.

Unfortunately I am not able to reproduce locally. I can't even reproduce it in our test environment. The exception only occurs in production.

Will continue the investigation. At least I know now that I haven't misunderstood how it is supposed to work.

[rabelenda]

Hi, I am facing a similar issue, using javanica 1.5.2.

I set the maxQueueSize and queueSizeRejectionThreshold for the particular thread pool (through the thread pool key, instead of default value provided in this ticket example), and I am getting a similar exception. I can't reproduce it locally either, but in production is happening some how. The error looks as if the maxQueueSize were set to a negative value and a sync queue were being used instead, but checking config in prod (we are using spring boot with spring cloud configs) both maxQueueSize and queueSizeRejectionThreshold seem to be properly set, and one seems to be taking effect (I see rejectionThreshold in exposed metrics, and hystrix stream) but the other not (the queue size, as the error says queued tasks = 0).

Any clues what might be happening, or where could I check to trace this issue? Any way you may come up with for checking the actual value that the instance of the pool is using, or type of queue, to verify if the config I am seeing is properly loaded into the thread pool instance and no side logic, or race condition in initialization may be happening?

Regards.

[mattrjacobs]

The Hystrix configuration stream reports all configuration. This is one way to inspect what the actual config is.

[rabelenda]

Thank you, will try including that in the application and check reported values.

[rabelenda]

The issue I was facing was effectively an initialization issue, and in particular with spring-boot + spring-cloud-netflix (using Brixton.SR7) and was mainly affecting the queue size configuration due to it's static nature (other properties can be changed on the fly).

I know is outside of the scope of hystrix but I will put some details just in case someone gets same issue and finds this hystrix issue: In my case some traffic going into spring-boot application through kafka (no web traffic, and kafka consumer initialized in a configuration class) was causing hystrix command (using @HystrixCommand annotation from javanica) to be created with default values from hystrix. When I tried issuing traffic through web interface, the configuration was being set properly in hystrix command. The root cause was ArchaiusAutoConfiguration not being initialized before the hystrix commands, so, as to solve the problem, I ended up including an @Import(ArchaiusAutoConfiguration.class) and @Inject private ArchaiusAutoConfiguration archaiusAutoConfiguration; in the root class annotated with @SpringBootApplication. This enforced such configuration to be initialized before any of my custom domain configuration. An alternate solution might be to use application listener to only start consuming from kafka once the application has finished starting. I guess there might be other solutions.

Regards, and thank you again for the information about the configuration stream :-).

[mattrjacobs]

Glad you got it solved - thanks for reporting back the details

[asarkar]

@rabelenda I ran into a similar issue (spring-cloud/spring-cloud-netflix#1950). I'm curious how did you conclude that the Hystrix command was created with default values, because you said Hystrix metrics stream was reporting the correct values.

[rabelenda]

Debugged application and analyzed Spring beans initialization debug logs. In the scenario it was not initializing properly, the ArchaiusAutoconfig bean was being created after the bean that used the hystrix command. Metrics were of no use since they didn't report queue size but rejection threshold. The links Matt shared should have provided (but I didn't try) further evidence of queue size initialized with defaults instead of configured sizes.

Regards.

[asarkar]

This is a discussion best had in the spring-cloud-netflix repo but for completeness sake, I'll continue the conversation on this thread.

@rabelenda Thanks for your response. It's not clear to me how you're creating your HystrixCommand. I've a Zuul filter with a Javanica @HystrixCommand annotation on a method. By adding a @PostConstruct method in the filter and putting breakpoints in it as well as various methods of ArchaiusAutoConfiguration, I can see ArchaiusAutoConfiguration being initialized after the filter @PostConstruct. Autowiring ArchaiusAutoConfiguration in the filter initializes it first. That proves what you said about the initialization order is true. However, that doesn't prove the Javanica @HystrixCommand is created with default values. Any ideas?

Edit:
By putting a breakpoint in com.netflix.hystrix.contrib.javanica.aop.aspectj.HystrixCommandAspect.methodsAnnotatedWithHystrixCommand(), I can see the Hystrix command being executed with the expected threadpool values. So in my case, the ArchaiusAutoConfiguration being initialized later is not an issue because the AOP is executed for every request. I'm guessing you may be creating your HystrixCommand when the bean is initialized, and thus facing the problem.

[rabelenda]

In my case even the @HystrixCommand annotated method was invoked before the ArchaiusAutoconfig.

[asarkar]

@rabelenda I can't reproduce the problem you're describing. Is it possible for you to create a sample app that demonstrates this issue? Note that I'm not challenging the fact that ArchaiusAutoConfiguration is loaded after your filter bean, but that Hystrix command is impacted by it.

Edit:
Your problem might be that before v1.5.9, the thread pool max size was always equals to the core size. I've verified this using versions before and after 1.5.9, and this is documented in the Wiki too. After 1.5.9, you can specify a different max size than core size, provided you also set allowMaximumSizeToDivergeFromCoreSize

[virendrabisht2006]

I am also facing similar issue, not able to reproduce the issue. I am using spring cloud dependency as Hoxton.RC1 and hystrix-core.1.5.18.
In my case my timeout works but thread pool configuration is not taking place. Below are the configuration.

hystrix:
command:
queryTimeOutHandler:
execution:
isolation:
thread:
timeoutInMilliseconds: 600000
threadpool:
queryTimeOutHandler:
coreSize: 200
maximumSize: 200
maxQueueSize: 100
queueSizeRejectionThreshold: 100
allowMaximumSizeToDivergeFromCoreSize: true

I still get exception for default thread pool configuration.
Task java.util.concurrent.FutureTask@69e8272b rejected from java.util.concurrent.ThreadPoolExecutor@51cd4319[Running, pool size = 10, active threads = 10, queued tasks = 0, completed tasks = 12759]

It says pool size 10, where as in my configuration coreSize: 200

Is there a way i can see these configuration once my service started in production?

[virendrabisht2006]

@mattrjacobs @rabelenda can you please help me on my question?

[sauga84]

Even in my case, i ran into similar issue (hysyrix-core-1.5.18).

Task java.util.concurrent.FutureTask@59c4b527 rejected from java.util.concurrent.ThreadPoolExecutor@51cd4319[Running, pool size = 10, active threads = 10, queued tasks = 0, completed tasks = 12759]

Any suggestions on this issue?