Skip to main content

[Date Prev][Date Next][Thread Prev][Thread Next][Date Index][Thread Index] [List Home]
Re: [jetty-users] Under load, requests are missing query parameters

Commercial support is available on Jetty 8 through webtide.com, we still have a number of clients running with Jetty 8 while they plot their migrations and updates.  But as Joakim notes, Jetty 8 is old enough that we just don't have the cycles to support it freely any longer and haven't for over a year now.

cheers,
Jesse

--
jesse mcconnell
jesse.mcconnell@xxxxxxxxx

On Fri, Dec 18, 2015 at 8:53 AM, Joakim Erdfelt <joakim@xxxxxxxxxxx> wrote:
Jetty 8 entered EOL (End of Life) over a year ago now.
Plenty of changes since then.

(Each of the below is considered a major version release by Jetty)

Jetty 9.0 (interim release between Servlet 3.0 and Servlet 3.1)
Jetty 9.1 (Final Servlet 3.1, Added JSR-356 Support)
Jetty 9.2 (Large refactor of internal Threading, finalize Java 8 support)
Jetty 9.3 (Drop SPDY, promote HTTP/2, Java 8 minimum requirement)

Jetty [master] is version 9.4 (no release yet) 

Since Jetty 8.1.8, there have been (up to version 9.3.6) ..
  • 4 Major version releases of stable Jetty
  • 70 Minor version releases of stable Jetty
  • 9,701 commits
  • 8,919 unique files modified
  • 5,572 files deleted
  • 480,773 lines of code changed (excluding deleted files)
The Request Object alone has had 1,736 modifications across 149 commits in that same time period.

Please try your analysis with something a bit more recent.

Try Jetty 9.2.14.v20151106 (if stuck on the EOL Java 7) or
use Jetty 9.3.6.v20151106 (if you are using Java 8 already)


Joakim Erdfelt / joakim@xxxxxxxxxxx

On Fri, Dec 18, 2015 at 4:39 AM, Dirk Olmes <dirk.olmes@xxxxxxxxxx> wrote:
Hello everyone,

under moderate load sometimes request parameters are missing from GET
requests. Here are my findings so far:

An instance of org.eclipse.jetty.server.AbstractHttpConnection keeps a
single instance of the Request - it does not create new Request objects
for each request-response loop it processes. At the end of a
request-response loop the recycle() method is called on the Request
object resetting its internal state.

In org.eclipse.jetty.server.Request, the _paramsExtracted instance
variable keeps track if the parameters need to be parsed or if that has
been done already. I have put additional logging into the Request object
to observe its behaviour. The typical set of method calls looks like this:

[qtp25126016-38] DEBUG: *** 13723614 setMethod GET
[qtp25126016-38] DEBUG: *** 13723614 entering getParameterMap
_paramsExtracted is false
[qtp25126016-38] DEBUG: *** 13723614 enter extractParameters
[qtp25126016-38] DEBUG: *** 13723614 setting _paramsExtracted to true: true
[qtp25126016-38] DEBUG: *** 13723614 parameters at end of
extractParameters: {renderer=html, device=screen, _=1450430929102}
[qtp25126016-38] DEBUG: *** 13723614 entering getParameterNames
_paramsExtracted is true
[qtp25126016-38] DEBUG: *** 13723614 entering getParameter(String)
_paramsExtracted is true
[qtp25126016-38] DEBUG: *** 13723614 entering getParameter(String)
_paramsExtracted is true
[qtp25126016-38] DEBUG: *** 13723614 entering getParameter(String)
_paramsExtracted is true
[qtp25126016-38] DEBUG: *** 13723614 recycle  _paramsExtracted :false

Note that I'm using the setMethod() call as the beginning of a
request-response loop and the call to recycle() as the end. The
"13723614" is the integer value of System.identityHashCode() of the
request object.

As the load on our app increases, we sometimes see the Request object
change for the same thread:

2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: *** 3358385 setMethod POST
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: new RequestDataImpl@16c6c9e
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: putting sessionId ->
1qz7t24ss14bj1gq3jvbpb2ay6
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: putting X-Forwarded-For
-> 192.168.21.112
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameter(String) _paramsExtracted is false
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: *** 3358385 enter
extractParameters
2015-12-18 10:30:37.135 [qtp25126016-39] DEBUG: *** 3358385 setting
_paramsExtracted to true: true
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: *** 3358385 parameters
at end of extractParameters: {compound=[xxx]}
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameter(String) _paramsExtracted is true
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameter(String) _paramsExtracted is true
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: putting cookie.username
-> xxx
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: putting
cookie.7b8c8f99-c403-4e60-8871-62a2a9288f07 ->
3a5e8e9f-08b4-4f0b-a0b8-4977c9f8b87f
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: POST:
--------------------------------------------------
2015-12-18 10:30:37.136 [qtp25126016-39] DEBUG: POST:
/pid3/ajax;jsessionid=1qz7t24ss14bj1gq3jvbpb2ay6
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameterMap _paramsExtracted is true
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameterNames _paramsExtracted is true
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: POST Parameter: compound
-> [xxx]
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: POST:
--------------------------------------------------
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameterNames _paramsExtracted is true
2015-12-18 10:30:37.137 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameterNames _paramsExtracted is true
2015-12-18 10:30:37.454 [qtp25126016-39] DEBUG: *** 13723614 entering
getParameter(String) _paramsExtracted is false
2015-12-18 10:30:37.454 [qtp25126016-39] DEBUG: *** 13723614 enter
extractParameters
2015-12-18 10:30:37.454 [qtp25126016-39] DEBUG: *** 13723614 setting
_paramsExtracted to true: true
2015-12-18 10:30:37.454 [qtp25126016-39] DEBUG: *** 13723614 parameters
at end of extractParameters: {}
2015-12-18 10:30:37.456 [qtp25126016-39] DEBUG: *** 3358385 entering
getParameter(String) _paramsExtracted is true
2015-12-18 10:30:37.457 [qtp25126016-39] DEBUG: *** 3358385 recycle
_paramsExtracted :false

Again, the lines marked with *** are the added debug output in the
Request object. I have added the thread name as the second info in each
line after the date. Note that while the thread stays the same, the
Request object changes in the last 3 lines.

Maybe I should also mention our environment:
- Linux 64 bit
- JDK 8u51
- Jetty 8.1.8.v20121106 - I know it's old. But I can reproduce the error
with Jetty 8.1.18.v20150929, too. As we configure Jetty from code, an
update to Jetty 9 is not an option right now :-(
- Right now we're using SelectChannelConnector that's default in the
Jetty Server class. But I can reproduce the bug using SocketConnector as
well.

This is as far as my analysis gets. I was hoping that someone on this
list may come up with suggestions or hints on how to analyze this further.

-dirk
_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


_______________________________________________
jetty-users mailing list
jetty-users@xxxxxxxxxxx
To change your delivery options, retrieve your password, or unsubscribe from this list, visit
https://dev.eclipse.org/mailman/listinfo/jetty-users


Back to the top