HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Previous Topic Next Topic
 
classic Classic list List threaded Threaded
29 messages Options
12
Reply | Threaded
Open this post in threaded view
|

Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

mgrigorov
Hi Arshiya,


On Fri, Oct 9, 2020 at 2:33 PM Arshiya Shariff
<[hidden email]> wrote:

> Hi,
>
> Mark , with the test runs that I performed over clean 9.0.x branch I was
> not able to reproduce this. But with 9.0.38 and the jars built from 9.0.x
> with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000
> users (connections) and on sending 1000 Requests per second (or even
> lesser) , payload of 16K  from JMeter I can see that this Exception occurs
> within few minutes of starting the test . The maxThreads configured in
> tomcat is 200 .
>
> How often do you see these errors in your test run?
> Randomly, at times 2 or 3 such traces.
>
> Do you have the other end of that stack trace?
> It is only the two lines that is recursively printed till the end about
> ~500 times in one trace  :
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>
> I see the trace starting with :
> Exception in thread "http-nio-x.y.z-1090-exec-107"
> java.lang.StackOverflowError
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>
>                 (OR)
>
> Exception in thread "http-nio-x.y.z-1090-exec-87"
> java.lang.StackOverflowError
>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         .....
>         .....
>         .....
>         .....
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>
> Is there anything that was fixed around this in latest 9.0.x branch ?
>

9.0.39 is being voted now at dev@ mailing list:

It can be obtained from:
https://dist.apache.org/repos/dist/dev/tomcat/tomcat-9/v9.0.39/
The Maven staging repo is:
https://repository.apache.org/content/repositories/orgapachetomcat-1281/

Give it a try and vote!


> Thanks and Regards
> Arshiya Shariff
>
> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Monday, October 5, 2020 9:52 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the connections to
> 1000/2000 (Embedded tomcat 9.0.38)
>
> On 05/10/2020 10:56, Arshiya Shariff wrote:
> > Hi All,
> >
> > Thank you so much Mark .
> > We tested the jars built from latest 9.0.x  with 2000 / 5000 users
> > (connections) from JMeter , We see a very good improvement with the
> > heap usage
>
> Good news. As is the fact that the other errors have been cleared up.
>
> > But I see this exception printed multiple times , I am not sure why this
> occurs :
> > Exception in thread "http-nio-x.y.z-1234-exec-213"
> java.lang.StackOverflowError
> >         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
> >         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
> >         at org.apache.tomcat.util.net
> .NioChannel.read(NioChannel.java:174)
> >         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
> >         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
> >         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
> >         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
> >         at org.apache.tomcat.util.net
> .NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
> >         at org.apache.tomcat.util.net
> .SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
> >         at
> > org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationSt
> > ate.run(NioEndpoint.java:1511)
>
> That looks like an infinite loop reading an incoming frame.
> New frames are read using a 9 byte buffer for the header and a 16k buffer
> for the payload (since Tomcat sets this as the max frame size).
>
> The loop is occurring because one of those buffers is simultaneously both
> full and still has more data to read. That should not be possible and I
> haven't yet been able to figure out how this is happening.
>
> How easy is this to reproduce?
>
> How often do you see these errors in your test run?
>
> Do you have a reliable test case that reproduces this on a clean Tomcat
> 9.0.x build? If is, can you share the details?
>
> Do you have the other end of that stack trace? I'm interested in how the
> code enters the loop.
>
> Thanks,
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
Reply | Threaded
Open this post in threaded view
|

Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

markt
In reply to this post by Arshiya Shariff
On 09/10/2020 12:32, Arshiya Shariff wrote:
> Hi,
>
> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.

Good. But I'd really like to understand why...

> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>
> How often do you see these errors in your test run?
> Randomly, at times 2 or 3 such traces.

OK. Definitely a timing issue then.

> Do you have the other end of that stack trace?
> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)

Doesn't tell me much unfortunately.

> I see the trace starting with :
> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>
>   (OR)
>
> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         .....
>         .....
>         .....
>         .....
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>
> Is there anything that was fixed around this in latest 9.0.x branch ?

Not obviously. I've reviewed every commit since c8ec2d4c. There is
nothing that directly works with the I/O. There is 1e97ab2 which fixes a
relatively recent regression in the HTTP/2 code. I guess it is possible
(but it seems a bit of a stretch) that that bug is triggering an issue
in JMeter which in turn is sending invalid HTTP/2 packets.

I think at this point, given the relatively small number of commits
between c8ec2d4c and HEAD, the most useful thing you could do is run a
binary search to find out at which commit the issue is fixed. If we know
which commit to look at that should help track down the root cause.

Mark

>
> Thanks and Regards
> Arshiya Shariff
>
> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Monday, October 5, 2020 9:52 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 05/10/2020 10:56, Arshiya Shariff wrote:
>> Hi All,
>>
>> Thank you so much Mark .
>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>> (connections) from JMeter , We see a very good improvement with the
>> heap usage
>
> Good news. As is the fact that the other errors have been cleared up.
>
>> But I see this exception printed multiple times , I am not sure why this occurs :
>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at
>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationSt
>> ate.run(NioEndpoint.java:1511)
>
> That looks like an infinite loop reading an incoming frame.
> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>
> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>
> How easy is this to reproduce?
>
> How often do you see these errors in your test run?
>
> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>
> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>
> Thanks,
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya Shariff
Hi Mark ,

The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.

Please find the case:
Client:JMeter 5.2.1 (With http2 plugin)
TPS: around 20
No of users from JMeter : 700
Message payload size: 6 KB to 34 KB
Loop: Infinite
We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.

Please help us with this . What is the impact of StackOverflowError ?

Thanks and Regards
Arshiya Shariff

-----Original Message-----
From: Mark Thomas <[hidden email]>
Sent: Friday, October 9, 2020 5:31 PM
To: [hidden email]
Subject: Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

On 09/10/2020 12:32, Arshiya Shariff wrote:
> Hi,
>
> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.

Good. But I'd really like to understand why...

> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>
> How often do you see these errors in your test run?
> Randomly, at times 2 or 3 such traces.

OK. Definitely a timing issue then.

> Do you have the other end of that stack trace?
> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at
> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
> er.completed(SocketWrapperBase.java:1100)

Doesn't tell me much unfortunately.

> I see the trace starting with :
> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at
> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
> er.completed(SocketWrapperBase.java:1100)
>
>   (OR)
>
> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         .....
>         .....
>         .....
>         .....
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>         at
> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
> er.completed(SocketWrapperBase.java:1100)
>
> Is there anything that was fixed around this in latest 9.0.x branch ?

Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.

I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.

Mark

>
> Thanks and Regards
> Arshiya Shariff
>
> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Monday, October 5, 2020 9:52 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the
> connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 05/10/2020 10:56, Arshiya Shariff wrote:
>> Hi All,
>>
>> Thank you so much Mark .
>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>> (connections) from JMeter , We see a very good improvement with the
>> heap usage
>
> Good news. As is the fact that the other errors have been cleared up.
>
>> But I see this exception printed multiple times , I am not sure why this occurs :
>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at
>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationS
>> t
>> ate.run(NioEndpoint.java:1511)
>
> That looks like an infinite loop reading an incoming frame.
> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>
> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>
> How easy is this to reproduce?
>
> How often do you see these errors in your test run?
>
> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>
> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>
> Thanks,
>
> Mark
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]
Reply | Threaded
Open this post in threaded view
|

Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

markt
On 12/10/2020 08:02, Arshiya Shariff wrote:

> Hi Mark ,
>
> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>
> Please find the case:
> Client:JMeter 5.2.1 (With http2 plugin)
> TPS: around 20
> No of users from JMeter : 700
> Message payload size: 6 KB to 34 KB
> Loop: Infinite
> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.

POSTing to what URL?

What does that URL do with the POSTed content? Ignore it? Read it from
an InputStream? Read it via getParameter()?

Is JMeter run on the same machine as Tomcat?

Do you use the JMeter GUI or the command line?

What are the specs of the server(s) being used?

You need to provide the exact steps to recreate this issue on a clean
install of Tomcat 9.0.39 as provided by the ASF.

Mark


> Please help us with this . What is the impact of StackOverflowError ?
>
> Thanks and Regards
> Arshiya Shariff
>
> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Friday, October 9, 2020 5:31 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 09/10/2020 12:32, Arshiya Shariff wrote:
>> Hi,
>>
>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>
> Good. But I'd really like to understand why...
>
>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>
>> How often do you see these errors in your test run?
>> Randomly, at times 2 or 3 such traces.
>
> OK. Definitely a timing issue then.
>
>> Do you have the other end of that stack trace?
>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
>> er.completed(SocketWrapperBase.java:1100)
>
> Doesn't tell me much unfortunately.
>
>> I see the trace starting with :
>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
>> er.completed(SocketWrapperBase.java:1100)
>>
>>   (OR)
>>
>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         .....
>>         .....
>>         .....
>>         .....
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandl
>> er.completed(SocketWrapperBase.java:1100)
>>
>> Is there anything that was fixed around this in latest 9.0.x branch ?
>
> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>
> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>
> Mark
>
>>
>> Thanks and Regards
>> Arshiya Shariff
>>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Monday, October 5, 2020 9:52 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>> Hi All,
>>>
>>> Thank you so much Mark .
>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>> (connections) from JMeter , We see a very good improvement with the
>>> heap usage
>>
>> Good news. As is the fact that the other errors have been cleared up.
>>
>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at
>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationS
>>> t
>>> ate.run(NioEndpoint.java:1511)
>>
>> That looks like an infinite loop reading an incoming frame.
>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>
>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>
>> How easy is this to reproduce?
>>
>> How often do you see these errors in your test run?
>>
>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>
>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>
>> Thanks,
>>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya Shariff
Hi ,

Please find the answers in-line Mark.

Http2 requests with message payload of  34KB are pumped from JMeter at 20 TPS with 700 connections to an application with Embedded tomcat - 9.0.39 (max-Threads : 200, all other values are the tomcat defaults)

What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?
The posted content is read via BufferedReader reader = request.getReader() and  processed asynchronously.

Is JMeter run on the same machine as Tomcat?
JMeter is run from a different machine.

Do you use the JMeter GUI or the command line?
Launched via Command line (JMeter heap increased to 10 GB )

What are the specs of the server(s) being used?
The server is a VM with 12 CPUs and 120 GB RAM

Please let us know  if you require more details.

Thanks and Regards
Arshiya Shariff
-----Original Message-----
From: Mark Thomas <[hidden email]>
Sent: Monday, October 12, 2020 7:28 PM
To: [hidden email]
Subject: Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

On 12/10/2020 08:02, Arshiya Shariff wrote:

> Hi Mark ,
>
> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>
> Please find the case:
> Client:JMeter 5.2.1 (With http2 plugin)
> TPS: around 20
> No of users from JMeter : 700
> Message payload size: 6 KB to 34 KB
> Loop: Infinite
> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.

POSTing to what URL?

What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?

Is JMeter run on the same machine as Tomcat?

Do you use the JMeter GUI or the command line?

What are the specs of the server(s) being used?

You need to provide the exact steps to recreate this issue on a clean install of Tomcat 9.0.39 as provided by the ASF.

Mark


> Please help us with this . What is the impact of StackOverflowError ?
>
> Thanks and Regards
> Arshiya Shariff
>
> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Friday, October 9, 2020 5:31 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the
> connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 09/10/2020 12:32, Arshiya Shariff wrote:
>> Hi,
>>
>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>
> Good. But I'd really like to understand why...
>
>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>
>> How often do you see these errors in your test run?
>> Randomly, at times 2 or 3 such traces.
>
> OK. Definitely a timing issue then.
>
>> Do you have the other end of that stack trace?
>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>> l
>> er.completed(SocketWrapperBase.java:1100)
>
> Doesn't tell me much unfortunately.
>
>> I see the trace starting with :
>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>> l
>> er.completed(SocketWrapperBase.java:1100)
>>
>>   (OR)
>>
>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         .....
>>         .....
>>         .....
>>         .....
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>         at
>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>> l
>> er.completed(SocketWrapperBase.java:1100)
>>
>> Is there anything that was fixed around this in latest 9.0.x branch ?
>
> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>
> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>
> Mark
>
>>
>> Thanks and Regards
>> Arshiya Shariff
>>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Monday, October 5, 2020 9:52 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>> Hi All,
>>>
>>> Thank you so much Mark .
>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>> (connections) from JMeter , We see a very good improvement with the
>>> heap usage
>>
>> Good news. As is the fact that the other errors have been cleared up.
>>
>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at
>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperation
>>> S
>>> t
>>> ate.run(NioEndpoint.java:1511)
>>
>> That looks like an infinite loop reading an incoming frame.
>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>
>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>
>> How easy is this to reproduce?
>>
>> How often do you see these errors in your test run?
>>
>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>
>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>
>> Thanks,
>>
>> Mark
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]
Reply | Threaded
Open this post in threaded view
|

Re: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Christopher Schultz-2
Arshiya,

On 10/14/20 01:23, Arshiya Shariff wrote:

> Please find the answers in-line Mark.
>
> Http2 requests with message payload of  34KB are pumped from JMeter
> at 20 TPS with 700 connections to an application with Embedded tomcat
> - 9.0.39 (max-Threads : 200, all other values are the tomcat
> defaults)
>
>> What does that URL do with the POSTed content? Ignore it? Read it
>> from an InputStream? Read it via getParameter()?
>
> The posted content is read via BufferedReader reader =
> request.getReader() and processed asynchronously
How... exactly?

> Is JMeter run on the same machine as Tomcat?
> JMeter is run from a different machine.
>
> Do you use the JMeter GUI or the command line?
> Launched via Command line (JMeter heap increased to 10 GB )
>
> What are the specs of the server(s) being used?
> The server is a VM with 12 CPUs and 120 GB RAM
>
> Please let us know  if you require more details.

This would probabyl be easier if you'd just provide a test-case: a
sample (simple!) web application which reproduces what you are reporting.

-chris

> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Monday, October 12, 2020 7:28 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 12/10/2020 08:02, Arshiya Shariff wrote:
>> Hi Mark ,
>>
>> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>>
>> Please find the case:
>> Client:JMeter 5.2.1 (With http2 plugin)
>> TPS: around 20
>> No of users from JMeter : 700
>> Message payload size: 6 KB to 34 KB
>> Loop: Infinite
>> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.
>
> POSTing to what URL?
>
> What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?
>
> Is JMeter run on the same machine as Tomcat?
>
> Do you use the JMeter GUI or the command line?
>
> What are the specs of the server(s) being used?
>
> You need to provide the exact steps to recreate this issue on a clean install of Tomcat 9.0.39 as provided by the ASF.
>
> Mark
>
>
>> Please help us with this . What is the impact of StackOverflowError ?
>>
>> Thanks and Regards
>> Arshiya Shariff
>>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Friday, October 9, 2020 5:31 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 09/10/2020 12:32, Arshiya Shariff wrote:
>>> Hi,
>>>
>>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>>
>> Good. But I'd really like to understand why...
>>
>>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>>
>>> How often do you see these errors in your test run?
>>> Randomly, at times 2 or 3 such traces.
>>
>> OK. Definitely a timing issue then.
>>
>>> Do you have the other end of that stack trace?
>>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>
>> Doesn't tell me much unfortunately.
>>
>>> I see the trace starting with :
>>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>>   (OR)
>>>
>>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         .....
>>>         .....
>>>         .....
>>>         .....
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHand
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>> Is there anything that was fixed around this in latest 9.0.x branch ?
>>
>> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>>
>> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>>
>> Mark
>>
>>>
>>> Thanks and Regards
>>> Arshiya Shariff
>>>
>>> -----Original Message-----
>>> From: Mark Thomas <[hidden email]>
>>> Sent: Monday, October 5, 2020 9:52 PM
>>> To: [hidden email]
>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>
>>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>>> Hi All,
>>>>
>>>> Thank you so much Mark .
>>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>>> (connections) from JMeter , We see a very good improvement with the
>>>> heap usage
>>>
>>> Good news. As is the fact that the other errors have been cleared up.
>>>
>>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at
>>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperation
>>>> S
>>>> t
>>>> ate.run(NioEndpoint.java:1511)
>>>
>>> That looks like an infinite loop reading an incoming frame.
>>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>>
>>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>>
>>> How easy is this to reproduce?
>>>
>>> How often do you see these errors in your test run?
>>>
>>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>>
>>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>>
>>> Thanks,
>>>
>>> Mark
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya Shariff
Hi,

Christopher, Please find the answer in-line:
How... exactly?
private String getRequestBody(HttpServletRequest request) throws IOException
        {
                StringBuilder sb = new StringBuilder();
                BufferedReader reader = request.getReader();
                try
                {
                        String line;
                        while( ( line = reader.readLine() ) != null )
                        {
                                sb.append( line ).append( '\n' );
                        }
                }
                finally
                {
                        reader.close();
                }
                return sb.toString();
        }
 
I am trying to reproduce the StackOverflowError with a sample application , Once it is reproduced I will share it across.

Thanks and Regards
Arshiya Shariff

-----Original Message-----
From: Christopher Schultz <[hidden email]>
Sent: Thursday, October 15, 2020 12:01 AM
To: [hidden email]
Subject: Re: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya,

On 10/14/20 01:23, Arshiya Shariff wrote:

> Please find the answers in-line Mark.
>
> Http2 requests with message payload of  34KB are pumped from JMeter at
> 20 TPS with 700 connections to an application with Embedded tomcat
> - 9.0.39 (max-Threads : 200, all other values are the tomcat
> defaults)
>
>> What does that URL do with the POSTed content? Ignore it? Read it
>> from an InputStream? Read it via getParameter()?
>
> The posted content is read via BufferedReader reader =
> request.getReader() and processed asynchronously
How... exactly?

> Is JMeter run on the same machine as Tomcat?
> JMeter is run from a different machine.
>
> Do you use the JMeter GUI or the command line?
> Launched via Command line (JMeter heap increased to 10 GB )
>
> What are the specs of the server(s) being used?
> The server is a VM with 12 CPUs and 120 GB RAM
>
> Please let us know  if you require more details.

This would probabyl be easier if you'd just provide a test-case: a sample (simple!) web application which reproduces what you are reporting.

-chris

> -----Original Message-----
> From: Mark Thomas <[hidden email]>
> Sent: Monday, October 12, 2020 7:28 PM
> To: [hidden email]
> Subject: Re: HTTP2: memory filled up fast on increasing the
> connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> On 12/10/2020 08:02, Arshiya Shariff wrote:
>> Hi Mark ,
>>
>> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>>
>> Please find the case:
>> Client:JMeter 5.2.1 (With http2 plugin)
>> TPS: around 20
>> No of users from JMeter : 700
>> Message payload size: 6 KB to 34 KB
>> Loop: Infinite
>> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.
>
> POSTing to what URL?
>
> What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?
>
> Is JMeter run on the same machine as Tomcat?
>
> Do you use the JMeter GUI or the command line?
>
> What are the specs of the server(s) being used?
>
> You need to provide the exact steps to recreate this issue on a clean install of Tomcat 9.0.39 as provided by the ASF.
>
> Mark
>
>
>> Please help us with this . What is the impact of StackOverflowError ?
>>
>> Thanks and Regards
>> Arshiya Shariff
>>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Friday, October 9, 2020 5:31 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 09/10/2020 12:32, Arshiya Shariff wrote:
>>> Hi,
>>>
>>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>>
>> Good. But I'd really like to understand why...
>>
>>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>>
>>> How often do you see these errors in your test run?
>>> Randomly, at times 2 or 3 such traces.
>>
>> OK. Definitely a timing issue then.
>>
>>> Do you have the other end of that stack trace?
>>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>> d
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>
>> Doesn't tell me much unfortunately.
>>
>>> I see the trace starting with :
>>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>> d
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>>   (OR)
>>>
>>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         .....
>>>         .....
>>>         .....
>>>         .....
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>         at
>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>> d
>>> l
>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>> Is there anything that was fixed around this in latest 9.0.x branch ?
>>
>> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>>
>> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>>
>> Mark
>>
>>>
>>> Thanks and Regards
>>> Arshiya Shariff
>>>
>>> -----Original Message-----
>>> From: Mark Thomas <[hidden email]>
>>> Sent: Monday, October 5, 2020 9:52 PM
>>> To: [hidden email]
>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>
>>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>>> Hi All,
>>>>
>>>> Thank you so much Mark .
>>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>>> (connections) from JMeter , We see a very good improvement with the
>>>> heap usage
>>>
>>> Good news. As is the fact that the other errors have been cleared up.
>>>
>>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at
>>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperatio
>>>> n
>>>> S
>>>> t
>>>> ate.run(NioEndpoint.java:1511)
>>>
>>> That looks like an infinite loop reading an incoming frame.
>>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>>
>>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>>
>>> How easy is this to reproduce?
>>>
>>> How often do you see these errors in your test run?
>>>
>>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>>
>>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>>
>>> Thanks,
>>>
>>> Mark
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]
Reply | Threaded
Open this post in threaded view
|

Re: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Christopher Schultz-2
Arshiya,

On 10/21/20 00:34, Arshiya Shariff wrote:

> Hi,
>
> Christopher, Please find the answer in-line:
> How... exactly?
> private String getRequestBody(HttpServletRequest request) throws IOException
> {
> StringBuilder sb = new StringBuilder();
> BufferedReader reader = request.getReader();
> try
> {
> String line;
> while( ( line = reader.readLine() ) != null )
> {
> sb.append( line ).append( '\n' );

Note that this may modify the incoming request. Are you sure you want to
return a value which does not match the exact POST body?

> }
> }
> finally
> {
> reader.close();
> }
> return sb.toString();
> }
>  

Is that method run from within the asynchronous context or before you
begin async processing? I'm not an expert at servlet-async, but I think
you should be reading the request entirely before entering the async
context. Reading the request from async may cause problems.

Instead of using blocking reads of the request bbody in asynchronous
mode, you should do this:

request.getInputStream().setReadListener(new ReadListener() {
  public void onoAllDataRead() { ... }
  public void onDataAvailable() { ... }
  public void onError(Throwable t) { ... }
});


> I am trying to reproduce the StackOverflowError with a sample
> application , Once it is reproduced I will share it across.

See https://www.slideshare.net/SimoneBordet/servlet-31-async-io

Specifically slides 43-53.

-chris

> -----Original Message-----
> From: Christopher Schultz <[hidden email]>
> Sent: Thursday, October 15, 2020 12:01 AM
> To: [hidden email]
> Subject: Re: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> Arshiya,
>
> On 10/14/20 01:23, Arshiya Shariff wrote:
>> Please find the answers in-line Mark.
>>
>> Http2 requests with message payload of  34KB are pumped from JMeter at
>> 20 TPS with 700 connections to an application with Embedded tomcat
>> - 9.0.39 (max-Threads : 200, all other values are the tomcat
>> defaults)
>>
>>> What does that URL do with the POSTed content? Ignore it? Read it
>>> from an InputStream? Read it via getParameter()?
>>
>> The posted content is read via BufferedReader reader =
>> request.getReader() and processed asynchronously
> How... exactly?
>> Is JMeter run on the same machine as Tomcat?
>> JMeter is run from a different machine.
>>
>> Do you use the JMeter GUI or the command line?
>> Launched via Command line (JMeter heap increased to 10 GB )
>>
>> What are the specs of the server(s) being used?
>> The server is a VM with 12 CPUs and 120 GB RAM
>>
>> Please let us know  if you require more details.
>
> This would probabyl be easier if you'd just provide a test-case: a sample (simple!) web application which reproduces what you are reporting.
>
> -chris
>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Monday, October 12, 2020 7:28 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 12/10/2020 08:02, Arshiya Shariff wrote:
>>> Hi Mark ,
>>>
>>> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>>>
>>> Please find the case:
>>> Client:JMeter 5.2.1 (With http2 plugin)
>>> TPS: around 20
>>> No of users from JMeter : 700
>>> Message payload size: 6 KB to 34 KB
>>> Loop: Infinite
>>> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.
>>
>> POSTing to what URL?
>>
>> What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?
>>
>> Is JMeter run on the same machine as Tomcat?
>>
>> Do you use the JMeter GUI or the command line?
>>
>> What are the specs of the server(s) being used?
>>
>> You need to provide the exact steps to recreate this issue on a clean install of Tomcat 9.0.39 as provided by the ASF.
>>
>> Mark
>>
>>
>>> Please help us with this . What is the impact of StackOverflowError ?
>>>
>>> Thanks and Regards
>>> Arshiya Shariff
>>>
>>> -----Original Message-----
>>> From: Mark Thomas <[hidden email]>
>>> Sent: Friday, October 9, 2020 5:31 PM
>>> To: [hidden email]
>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>
>>> On 09/10/2020 12:32, Arshiya Shariff wrote:
>>>> Hi,
>>>>
>>>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>>>
>>> Good. But I'd really like to understand why...
>>>
>>>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>>>
>>>> How often do you see these errors in your test run?
>>>> Randomly, at times 2 or 3 such traces.
>>>
>>> OK. Definitely a timing issue then.
>>>
>>>> Do you have the other end of that stack trace?
>>>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>> Doesn't tell me much unfortunately.
>>>
>>>> I see the trace starting with :
>>>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>>
>>>>   (OR)
>>>>
>>>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         .....
>>>>         .....
>>>>         .....
>>>>         .....
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHan
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>>
>>>> Is there anything that was fixed around this in latest 9.0.x branch ?
>>>
>>> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>>>
>>> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>>>
>>> Mark
>>>
>>>>
>>>> Thanks and Regards
>>>> Arshiya Shariff
>>>>
>>>> -----Original Message-----
>>>> From: Mark Thomas <[hidden email]>
>>>> Sent: Monday, October 5, 2020 9:52 PM
>>>> To: [hidden email]
>>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>>
>>>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>>>> Hi All,
>>>>>
>>>>> Thank you so much Mark .
>>>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>>>> (connections) from JMeter , We see a very good improvement with the
>>>>> heap usage
>>>>
>>>> Good news. As is the fact that the other errors have been cleared up.
>>>>
>>>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at
>>>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperatio
>>>>> n
>>>>> S
>>>>> t
>>>>> ate.run(NioEndpoint.java:1511)
>>>>
>>>> That looks like an infinite loop reading an incoming frame.
>>>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>>>
>>>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>>>
>>>> How easy is this to reproduce?
>>>>
>>>> How often do you see these errors in your test run?
>>>>
>>>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>>>
>>>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>>>
>>>> Thanks,
>>>>
>>>> Mark
>>>>
>>>> --------------------------------------------------------------------
>>>> - To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>>
>>>> --------------------------------------------------------------------
>>>> - To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>> ---------------------------------------------------------------------
>>> To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]

Reply | Threaded
Open this post in threaded view
|

RE: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya Shariff
Hi all,

Thanks for the update Christopher.

I tried modifying our application as below i.e by adding a read Listener and processing the requests after all the data is read (onDataAvailable()) .
But I can still see the StackOverFlow Error printed .

                AsyncContext asyncContext = req.startAsync( req, resp );
                ServletInputStream input = req.getInputStream();
                ReadListenerImpl listener = new ReadListenerImpl( input, asyncContext, req, resp, map, myExecutor, this );
                input.setReadListener( listener );
                . . .
                public class ReadListenerImpl implements ReadListener
                        {
                                .
                                .
                                .
                                @Override
                                public void onDataAvailable() throws IOException
                                {
                                        int len = -1;
                                        byte b[] = new byte[4 * 1024];
                                        while( input.isReady() && !input.isFinished() )
                                        {
                                                len = input.read( b );
                                                if( len > 0 )
                                                {
                                                        String data = new String( b, 0, len );
                                                        sb.append( data );
                                                }
                                        }
                                }

                                @Override
                                public void onError(Throwable throwable)
                                {
                                        asyncContext.complete();
                                        throwable.printStackTrace();

                                }
                                @Override
                                public void onAllDataRead() throws IOException
                                {
                                        String jsonData = sb.toString();
                                        .
                                        .
                                        .
                                }
                        }

Unfortunately I am still not able to reproduce this exception with a test code , I am trying .

Thanks and Regards
Arshiya Shariff


-----Original Message-----
From: Christopher Schultz <[hidden email]>
Sent: Wednesday, October 21, 2020 7:53 PM
To: [hidden email]
Subject: Re: FW: HTTP2: memory filled up fast on increasing the connections to 1000/2000 (Embedded tomcat 9.0.38)

Arshiya,

On 10/21/20 00:34, Arshiya Shariff wrote:

> Hi,
>
> Christopher, Please find the answer in-line:
> How... exactly?
> private String getRequestBody(HttpServletRequest request) throws IOException
> {
> StringBuilder sb = new StringBuilder();
> BufferedReader reader = request.getReader();
> try
> {
> String line;
> while( ( line = reader.readLine() ) != null )
> {
> sb.append( line ).append( '\n' );

Note that this may modify the incoming request. Are you sure you want to return a value which does not match the exact POST body?

> }
> }
> finally
> {
> reader.close();
> }
> return sb.toString();
> }
>  

Is that method run from within the asynchronous context or before you begin async processing? I'm not an expert at servlet-async, but I think you should be reading the request entirely before entering the async context. Reading the request from async may cause problems.

Instead of using blocking reads of the request bbody in asynchronous mode, you should do this:

request.getInputStream().setReadListener(new ReadListener() {
  public void onoAllDataRead() { ... }
  public void onDataAvailable() { ... }
  public void onError(Throwable t) { ... } });


> I am trying to reproduce the StackOverflowError with a sample
> application , Once it is reproduced I will share it across.

See https://www.slideshare.net/SimoneBordet/servlet-31-async-io

Specifically slides 43-53.

-chris

> -----Original Message-----
> From: Christopher Schultz <[hidden email]>
> Sent: Thursday, October 15, 2020 12:01 AM
> To: [hidden email]
> Subject: Re: FW: HTTP2: memory filled up fast on increasing the
> connections to 1000/2000 (Embedded tomcat 9.0.38)
>
> Arshiya,
>
> On 10/14/20 01:23, Arshiya Shariff wrote:
>> Please find the answers in-line Mark.
>>
>> Http2 requests with message payload of  34KB are pumped from JMeter
>> at
>> 20 TPS with 700 connections to an application with Embedded tomcat
>> - 9.0.39 (max-Threads : 200, all other values are the tomcat
>> defaults)
>>
>>> What does that URL do with the POSTed content? Ignore it? Read it
>>> from an InputStream? Read it via getParameter()?
>>
>> The posted content is read via BufferedReader reader =
>> request.getReader() and processed asynchronously
> How... exactly?
>> Is JMeter run on the same machine as Tomcat?
>> JMeter is run from a different machine.
>>
>> Do you use the JMeter GUI or the command line?
>> Launched via Command line (JMeter heap increased to 10 GB )
>>
>> What are the specs of the server(s) being used?
>> The server is a VM with 12 CPUs and 120 GB RAM
>>
>> Please let us know  if you require more details.
>
> This would probabyl be easier if you'd just provide a test-case: a sample (simple!) web application which reproduces what you are reporting.
>
> -chris
>
>> -----Original Message-----
>> From: Mark Thomas <[hidden email]>
>> Sent: Monday, October 12, 2020 7:28 PM
>> To: [hidden email]
>> Subject: Re: HTTP2: memory filled up fast on increasing the
>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>
>> On 12/10/2020 08:02, Arshiya Shariff wrote:
>>> Hi Mark ,
>>>
>>> The issue is reproduced with version 9.0.39 as well. Max threads in Tomcat is 200.
>>>
>>> Please find the case:
>>> Client:JMeter 5.2.1 (With http2 plugin)
>>> TPS: around 20
>>> No of users from JMeter : 700
>>> Message payload size: 6 KB to 34 KB
>>> Loop: Infinite
>>> We let the loop run infinitely and see the java.lang.StackOverflowError trace printed multiple times in the log within few minutes of starting the test.
>>
>> POSTing to what URL?
>>
>> What does that URL do with the POSTed content? Ignore it? Read it from an InputStream? Read it via getParameter()?
>>
>> Is JMeter run on the same machine as Tomcat?
>>
>> Do you use the JMeter GUI or the command line?
>>
>> What are the specs of the server(s) being used?
>>
>> You need to provide the exact steps to recreate this issue on a clean install of Tomcat 9.0.39 as provided by the ASF.
>>
>> Mark
>>
>>
>>> Please help us with this . What is the impact of StackOverflowError ?
>>>
>>> Thanks and Regards
>>> Arshiya Shariff
>>>
>>> -----Original Message-----
>>> From: Mark Thomas <[hidden email]>
>>> Sent: Friday, October 9, 2020 5:31 PM
>>> To: [hidden email]
>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>
>>> On 09/10/2020 12:32, Arshiya Shariff wrote:
>>>> Hi,
>>>>
>>>> Mark , with the test runs that I performed over clean 9.0.x branch I was not able to reproduce this.
>>>
>>> Good. But I'd really like to understand why...
>>>
>>>> But with 9.0.38 and the jars built from 9.0.x with hash: c8ec2d4cde3a31b0e9df9a30e7915d77ba725545  , with 700 or 1000 users (connections) and on sending 1000 Requests per second (or even lesser) , payload of 16K  from JMeter I can see that this Exception occurs within few minutes of starting the test . The maxThreads configured in tomcat is 200 .
>>>>
>>>> How often do you see these errors in your test run?
>>>> Randomly, at times 2 or 3 such traces.
>>>
>>> OK. Definitely a timing issue then.
>>>
>>>> Do you have the other end of that stack trace?
>>>> It is only the two lines that is recursively printed till the end about  ~500 times in one trace  :
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHa
>>>> n
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>
>>> Doesn't tell me much unfortunately.
>>>
>>>> I see the trace starting with :
>>>> Exception in thread "http-nio-x.y.z-1090-exec-107" java.lang.StackOverflowError
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:446)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHa
>>>> n
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>>
>>>>   (OR)
>>>>
>>>> Exception in thread "http-nio-x.y.z-1090-exec-87" java.lang.StackOverflowError
>>>>         at sun.nio.ch.IOVecWrapper.get(IOVecWrapper.java:96)
>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         .....
>>>>         .....
>>>>         .....
>>>>         .....
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>         at
>>>> org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHa
>>>> n
>>>> d
>>>> l
>>>> er.completed(SocketWrapperBase.java:1100)
>>>>
>>>> Is there anything that was fixed around this in latest 9.0.x branch ?
>>>
>>> Not obviously. I've reviewed every commit since c8ec2d4c. There is nothing that directly works with the I/O. There is 1e97ab2 which fixes a relatively recent regression in the HTTP/2 code. I guess it is possible (but it seems a bit of a stretch) that that bug is triggering an issue in JMeter which in turn is sending invalid HTTP/2 packets.
>>>
>>> I think at this point, given the relatively small number of commits between c8ec2d4c and HEAD, the most useful thing you could do is run a binary search to find out at which commit the issue is fixed. If we know which commit to look at that should help track down the root cause.
>>>
>>> Mark
>>>
>>>>
>>>> Thanks and Regards
>>>> Arshiya Shariff
>>>>
>>>> -----Original Message-----
>>>> From: Mark Thomas <[hidden email]>
>>>> Sent: Monday, October 5, 2020 9:52 PM
>>>> To: [hidden email]
>>>> Subject: Re: HTTP2: memory filled up fast on increasing the
>>>> connections to 1000/2000 (Embedded tomcat 9.0.38)
>>>>
>>>> On 05/10/2020 10:56, Arshiya Shariff wrote:
>>>>> Hi All,
>>>>>
>>>>> Thank you so much Mark .
>>>>> We tested the jars built from latest 9.0.x  with 2000 / 5000 users
>>>>> (connections) from JMeter , We see a very good improvement with
>>>>> the heap usage
>>>>
>>>> Good news. As is the fact that the other errors have been cleared up.
>>>>
>>>>> But I see this exception printed multiple times , I am not sure why this occurs :
>>>>> Exception in thread "http-nio-x.y.z-1234-exec-213" java.lang.StackOverflowError
>>>>>         at sun.nio.ch.IOUtil.read(IOUtil.java:240)
>>>>>         at sun.nio.ch.SocketChannelImpl.read(SocketChannelImpl.java:440)
>>>>>         at org.apache.tomcat.util.net.NioChannel.read(NioChannel.java:174)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1468)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperationState.run(NioEndpoint.java:1511)
>>>>>         at org.apache.tomcat.util.net.SocketWrapperBase$VectoredIOCompletionHandler.completed(SocketWrapperBase.java:1100)
>>>>>         at
>>>>> org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper$NioOperati
>>>>> o
>>>>> n
>>>>> S
>>>>> t
>>>>> ate.run(NioEndpoint.java:1511)
>>>>
>>>> That looks like an infinite loop reading an incoming frame.
>>>> New frames are read using a 9 byte buffer for the header and a 16k buffer for the payload (since Tomcat sets this as the max frame size).
>>>>
>>>> The loop is occurring because one of those buffers is simultaneously both full and still has more data to read. That should not be possible and I haven't yet been able to figure out how this is happening.
>>>>
>>>> How easy is this to reproduce?
>>>>
>>>> How often do you see these errors in your test run?
>>>>
>>>> Do you have a reliable test case that reproduces this on a clean Tomcat 9.0.x build? If is, can you share the details?
>>>>
>>>> Do you have the other end of that stack trace? I'm interested in how the code enters the loop.
>>>>
>>>> Thanks,
>>>>
>>>> Mark
>>>>
>>>> -------------------------------------------------------------------
>>>> -
>>>> - To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>>
>>>> -------------------------------------------------------------------
>>>> -
>>>> - To unsubscribe, e-mail: [hidden email]
>>>> For additional commands, e-mail: [hidden email]
>>>>
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>>
>>> --------------------------------------------------------------------
>>> - To unsubscribe, e-mail: [hidden email]
>>> For additional commands, e-mail: [hidden email]
>>>
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>>
>> ---------------------------------------------------------------------
>> To unsubscribe, e-mail: [hidden email]
>> For additional commands, e-mail: [hidden email]
>>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>
>
> ---------------------------------------------------------------------
> To unsubscribe, e-mail: [hidden email]
> For additional commands, e-mail: [hidden email]
>

---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]


---------------------------------------------------------------------
To unsubscribe, e-mail: [hidden email]
For additional commands, e-mail: [hidden email]
12