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

Fix for the monitoring jetty9 async servlet requests. #1074

Merged
merged 1 commit into from Feb 17, 2017

Conversation

Projects
None yet
5 participants
@arteam
Member

arteam commented Feb 17, 2017

Async requests are monitored via the addition of an async listener.
The bug was that onStartAsync(AsyncEvent) is called when the handler
invokes startAsync() but the InstrumentedHandler only added the
listener after the call to the delegate handler, thus would miss
the all onStartAsync event.

The net result of the bug was that the start time of all async requests
was reported as 0 so the calculated elapsed times where then rather
large (i.e. currentTimeMillis()).

Fix for the monitoring jetty9 async servlet requests.
Async requests are monitored via the addition of an async listener.
The bug was that `onStartAsync(AsyncEvent)` is called when the handler
invokes `startAsync()` but the `InstrumentedHandler` only added the
listener after the call to the delegate handler, thus would miss
the all onStartAsync event.

The net result of the bug was that the start time of all async requests
was reported as 0 so the calculated elapsed times where then rather
large (i.e. currentTimeMillis()).
@arteam

This comment has been minimized.

Show comment
Hide comment
@arteam

arteam Feb 17, 2017

Member

This is the work of @tempredirect in #715 rebased to the 3.2 branch.

Member

arteam commented Feb 17, 2017

This is the work of @tempredirect in #715 rebased to the 3.2 branch.

@ryantenney

This comment has been minimized.

Show comment
Hide comment
@ryantenney

ryantenney Feb 17, 2017

Member

LGTM

Member

ryantenney commented Feb 17, 2017

LGTM

@arteam arteam merged commit 7976644 into 3.2-development Feb 17, 2017

2 checks passed

continuous-integration/travis-ci/pr The Travis CI build passed
Details
continuous-integration/travis-ci/push The Travis CI build passed
Details

@arteam arteam deleted the tempredirect-fix_jetty9_async branch Feb 17, 2017

@tempredirect

This comment has been minimized.

Show comment
Hide comment
@tempredirect

tempredirect Feb 17, 2017

Great work, thank you for doing this.

tempredirect commented Feb 17, 2017

Great work, thank you for doing this.

@tnn

This comment has been minimized.

Show comment
Hide comment
@tnn

tnn Feb 14, 2018

Hi @arteam, we just observed this on 3.2.3, 3.2.6 and 4.0.2:

jetty_active_requests -4.0
jetty_active_suspended -5.0

We have verified this on multiple systems. The service were this is observed, uses the following setup:
jetty: 9.4.8.v20171121
jersey: 2.25.1
Java: 9.0.0 and 9.0.4.

We are using Jersey/JAX-RS AsyncResponse. We have inspected the heap and thread - and found no evidence that the AsyncResponse has not properly been resumed. We have verified both running as -jar and jmod.

It appears that a request is immediately completed (buffered by Jersey), but still a AsyncResponse, the if (state.isSuspended()) branch in InstrumentedHandler is never hit, because while the request has state (HttpChanelState):

_state = {org.eclipse.jetty.server.HttpChannelState$State@7071} "DISPATCHED"
_async = {org.eclipse.jetty.server.HttpChannelState$Async@7072} "COMPLETE"
_asyncRead = {org.eclipse.jetty.server.HttpChannelState$AsyncRead@7073} "IDLE"

The state while incrementing (line 224, if (state.isInitial()) {):

_state = {org.eclipse.jetty.server.HttpChannelState$State@7071} "DISPATCHED"
_async = {org.eclipse.jetty.server.HttpChannelState$Async@7229} "NOT_ASYNC"
_asyncRead = {org.eclipse.jetty.server.HttpChannelState$AsyncRead@7073} "IDLE"

So it appears that the activeSuspended.dec(); on line 232 needs to take into account if the request is async, is completed and that the async state has gone from NOT_ASYNC to COMPLETE.

Please let us know, if we can help in anyway.

Cross posted as an issue: #1324.

tnn commented Feb 14, 2018

Hi @arteam, we just observed this on 3.2.3, 3.2.6 and 4.0.2:

jetty_active_requests -4.0
jetty_active_suspended -5.0

We have verified this on multiple systems. The service were this is observed, uses the following setup:
jetty: 9.4.8.v20171121
jersey: 2.25.1
Java: 9.0.0 and 9.0.4.

We are using Jersey/JAX-RS AsyncResponse. We have inspected the heap and thread - and found no evidence that the AsyncResponse has not properly been resumed. We have verified both running as -jar and jmod.

It appears that a request is immediately completed (buffered by Jersey), but still a AsyncResponse, the if (state.isSuspended()) branch in InstrumentedHandler is never hit, because while the request has state (HttpChanelState):

_state = {org.eclipse.jetty.server.HttpChannelState$State@7071} "DISPATCHED"
_async = {org.eclipse.jetty.server.HttpChannelState$Async@7072} "COMPLETE"
_asyncRead = {org.eclipse.jetty.server.HttpChannelState$AsyncRead@7073} "IDLE"

The state while incrementing (line 224, if (state.isInitial()) {):

_state = {org.eclipse.jetty.server.HttpChannelState$State@7071} "DISPATCHED"
_async = {org.eclipse.jetty.server.HttpChannelState$Async@7229} "NOT_ASYNC"
_asyncRead = {org.eclipse.jetty.server.HttpChannelState$AsyncRead@7073} "IDLE"

So it appears that the activeSuspended.dec(); on line 232 needs to take into account if the request is async, is completed and that the async state has gone from NOT_ASYNC to COMPLETE.

Please let us know, if we can help in anyway.

Cross posted as an issue: #1324.

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