Skip to content
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.

Sign up for GitHub

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

Jump to bottom

It takes 13 seconds till we get a short-circuit exception so the request is stuck. #1673

Open
reevik opened this issue Sep 4, 2017 · 1 comment
Open

It takes 13 seconds till we get a short-circuit exception so the request is stuck. #1673

reevik opened this issue Sep 4, 2017 · 1 comment

Comments

@reevik
Copy link

reevik commented Sep 4, 2017 •
edited

We use Hystrix 1.4.26 and no fallback for the hystrix command mentioned below. It takes about 13 seconds till we get finally a short-circuit exception [1] so the whole request take over 15 secs. We use following isolation configuration for the thread and the command group:

command.MemcacheSetCommand.execution.isolation.thread.timeoutInMilliseconds = 1000
threadpool.default.maxQueueSize = -1
threadpool.memcached.coreSize = 200
threadpool.memcached.maxQueueSize = 150
threadpool.memcached.queueSizeRejectionThreshold = 150

Somewhere, the execution seems to be stuck and I found many repeating calls in the stacktrace. Anyone can help me out here?

PS: We have no fallback for the command.

[1]
2017-08-18 19:33:09,650 | FATAL | qtp1727387186-432 | sc.Connector | f9803a2f6318235e15030703110967510268 | Failed to store root collection ID c9937f89-a72f-5ee4-8719-4bb40f5a4ec1 in cache. Proceeding anyways.
com.netflix.hystrix.exception.HystrixRuntimeException: MemcacheSetCommand short-circuited and no fallback available.
at com.netflix.hystrix.AbstractCommand$16.call(AbstractCommand.java:806)
at com.netflix.hystrix.AbstractCommand$16.call(AbstractCommand.java:790)
at rx.internal.operators.OperatorOnErrorResumeNextViaFunction$4.onError(OperatorOnErrorResumeNextViaFunction.java:140)
at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:72)
at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:72)
at rx.internal.operators.OperatorDoOnEach$1.onError(OperatorDoOnEach.java:72)
at com.netflix.hystrix.AbstractCommand$DeprecatedOnFallbackHookApplication$1.onError(AbstractCommand.java:1519)
at com.netflix.hystrix.AbstractCommand$FallbackHookApplication$1.onError(AbstractCommand.java:1409)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:314)
at com.netflix.hystrix.HystrixCommand$2.call(HystrixCommand.java:306)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.Observable.unsafeSubscribe(Observable.java:9860)
at com.netflix.hystrix.AbstractCommand$1.call(AbstractCommand.java:417)
at com.netflix.hystrix.AbstractCommand$1.call(AbstractCommand.java:363)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.Observable.unsafeSubscribe(Observable.java:9860)
at com.netflix.hystrix.AbstractCommand$ObservableCommand$1.call(AbstractCommand.java:1138)
at com.netflix.hystrix.AbstractCommand$ObservableCommand$1.call(AbstractCommand.java:1134)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:48)
at rx.internal.operators.OnSubscribeLift.call(OnSubscribeLift.java:30)
at rx.Observable.subscribe(Observable.java:9956)
at rx.Observable.subscribe(Observable.java:9923)
at rx.internal.operators.BlockingOperatorToFuture.toFuture(BlockingOperatorToFuture.java:51)
at rx.observables.BlockingObservable.toFuture(BlockingObservable.java:412)
at com.netflix.hystrix.HystrixCommand.queue(HystrixCommand.java:379)
at c.a.s.webapi.internal.memcached.MemcachedClient.set(MemcachedClient.java:74)
at c.a.s.sync.connector.internal.sc.Connector.getRootCollectionId(Connector.java:377)
at c.a.s.sync.webapi.internal.resources.GetRootCollectionIdCommand.call(GetRootCollectionIdCommand.java:60)
at c.a.s.sync.webapi.internal.resources.ResourcesController.getRootCollectionId(ResourcesController.java:146)
at c.a.s.sync.webapi.internal.resources.ResourcesResource.getLinks(ResourcesResource.java:715)
at c.a.s.webapi.internal.core.LinkProviderAggregator.getLinks(LinkProviderAggregator.java:48)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.RootResource.retrieveJSONTextVersionInfo(RootResource.java:213)[75:c.a.s.webapi.core:0.0.1.695]
at sun.reflect.GeneratedMethodAccessor42.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)[:1.8.0_101]
at java.lang.reflect.Method.invoke(Method.java:498)[:1.8.0_101]
at com.sun.jersey.spi.container.JavaMethodInvokerFactory$1.invoke(JavaMethodInvokerFactory.java:60)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.model.method.dispatch.AbstractResourceMethodDispatchProvider$JResponseOutInvoker._dispatch(AbstractResourceMethodDispatchProvider.java:236)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.model.method.dispatch.ResourceJavaMethodDispatcher.dispatch(ResourceJavaMethodDispatcher.java:75)[57:com.sun.jersey.jersey-server:1.17.1]
at com.codahale.metrics.jersey.InstrumentedResourceMethodDispatchProvider$TimedRequestDispatcher.dispatch(InstrumentedResourceMethodDispatchProvider.java:30)[23:com.codahale.metrics.jersey:3.0.0]
at com.sun.jersey.server.impl.uri.rules.HttpMethodRule.accept(HttpMethodRule.java:302)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.uri.rules.ResourceObjectRule.accept(ResourceObjectRule.java:100)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.uri.rules.RightHandPathRule.accept(RightHandPathRule.java:147)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.uri.rules.RootResourceClassesRule.accept(RootResourceClassesRule.java:84)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1511)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.application.WebApplicationImpl._handleRequest(WebApplicationImpl.java:1442)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1391)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.server.impl.application.WebApplicationImpl.handleRequest(WebApplicationImpl.java:1381)[57:com.sun.jersey.jersey-server:1.17.1]
at com.sun.jersey.spi.container.servlet.WebComponent.service(WebComponent.java:416)[58:com.sun.jersey.servlet:1.17.1]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:538)[58:com.sun.jersey.servlet:1.17.1]
at com.sun.jersey.spi.container.servlet.ServletContainer.service(ServletContainer.java:716)[58:com.sun.jersey.servlet:1.17.1]
at javax.servlet.http.HttpServlet.service(HttpServlet.java:668)[34:org.apache.geronimo.specs.geronimo-servlet_3.0_spec:1.0.0]
at c.a.s.webapi.internal.core.GenericServletWrapper.service(GenericServletWrapper.java:135)[75:c.a.s.webapi.core:0.0.1.695]
at org.eclipse.jetty.servlet.ServletHolder.handle(ServletHolder.java:684)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1496)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:150)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.LoggingFilter.doFilter(LoggingFilter.java:115)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:148)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.CallContextFilter.doFilter(CallContextFilter.java:166)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:148)[75:c.a.s.webapi.core:0.0.1.695]
at com.codahale.metrics.servlet.AbstractInstrumentedFilter.doFilter(AbstractInstrumentedFilter.java:97)[24:com.codahale.metrics.servlet:3.0.0]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:148)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.InputStreamServletFilter.doFilter(InputStreamServletFilter.java:52)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:148)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.PerformanceTrackingFilter.doFilter(PerformanceTrackingFilter.java:46)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.UberFilter$UberChain.doFilter(UberFilter.java:148)[75:c.a.s.webapi.core:0.0.1.695]
at c.a.s.webapi.internal.core.UberFilter.doFilter(UberFilter.java:81)[75:c.a.s.webapi.core:0.0.1.695]
at org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1467)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:501)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceServletHandler.doHandle(HttpServiceServletHandler.java:69)[49:org.ops4j.pax.web.pax-web-jetty:3.2.2]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:137)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:557)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:231)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1086)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.ops4j.pax.web.service.jetty.internal.HttpServiceContext.doHandle(HttpServiceContext.java:240)[49:org.ops4j.pax.web.pax-web-jetty:3.2.2]
at org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:429)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:193)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1020)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:135)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.ops4j.pax.web.service.jetty.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:75)[49:org.ops4j.pax.web.pax-web-jetty:3.2.2]
at org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:116)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.Server.handle(Server.java:370)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.AbstractHttpConnection.handleRequest(AbstractHttpConnection.java:494)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.AbstractHttpConnection.headerComplete(AbstractHttpConnection.java:971)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.AbstractHttpConnection$RequestHandler.headerComplete(AbstractHttpConnection.java:1033)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.http.HttpParser.parseNext(HttpParser.java:644)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.http.HttpParser.parseAvailable(HttpParser.java:235)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.server.AsyncHttpConnection.handle(AsyncHttpConnection.java:82)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.io.nio.SelectChannelEndPoint.handle(SelectChannelEndPoint.java:696)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.io.nio.SelectChannelEndPoint$1.run(SelectChannelEndPoint.java:53)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:608)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at org.eclipse.jetty.util.thread.QueuedThreadPool$3.run(QueuedThreadPool.java:543)[40:org.eclipse.jetty.aggregate.jetty-all-server:8.1.16.v20140903]
at java.lang.Thread.run(Thread.java:745)[:1.8.0_101]
Caused by: java.lang.RuntimeException: Hystrix circuit short-circuited and is OPEN
at com.netflix.hystrix.AbstractCommand$1.call(AbstractCommand.java:414)
... 86 more
@reevik reevik changed the title It takes 13 seconds till we get an short-circuit exception so the request stucks It takes 13 seconds till we get a short-circuit exception so the request stucks Sep 4, 2017
@reevik reevik changed the title It takes 13 seconds till we get a short-circuit exception so the request stucks It takes 13 seconds till we get a short-circuit exception so the request is stuck. Sep 4, 2017
@Till--H
Copy link

Till--H commented Feb 6, 2018 •
edited

Hi,

i have the same problem in my application using Hystrix. Seems to happen when the application is under high load.
From what I saw, the evaluation if a circuit is open (i.e., the request should be rejected) happens inside an Observable, so quite a bit of overhead for rejecting the request.
Would it be possible to do the evaluation if the request should be executed or not (depending on circuits state) earlier, so that is it less likely to waste time before rejecting the request?

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
None yet
Projects
None yet
Milestone
No milestone
Development

No branches or pull requests
2 participants
@reevik @Till--H