throwing static exceptions sometimes VERY slow!

classic Classic list List threaded Threaded
9 messages Options
Reply | Threaded
Open this post in threaded view
|

throwing static exceptions sometimes VERY slow!

Wieland, Jacob
Hi,


I am observing a very strange behavior.


In our generated code (due to various reasons I won't go into here unless I have to, but trust me, they are legit), we throw static exceptions for control flow purposes, This seems to work fine and without performance loss most of the time. However, we are observing now that every few seconds, a throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the normal almost non-measurable time).


Update: it seems that the observed behavior was kind of related with some extraneous circumstances (the computer seems to have been more lagged than usual at that point). By now, I can only observe throws that take up to 20 milliseconds (which opposed to the normal time still seems slow).


It does not seem to be GC related, the only idea that I have is the jitter.


So, my question is. Is this a known (and for some strange reason maybe even accepted) behavior or is this a bug that I should file with Oracle (or you guys).


BR


[X]




Dr. Jacob Wieland

Senior Software Engineer

main    +49.30.7261919.34

mobile +49.173.6446443


[hidden email]<mailto:[hidden email]>


www.spirent.com








Follow us on:




Spirent Communications


<https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>|<https://twitter.com/Spirent>[X]<https://twitter.com/Spirent>|<https://www.facebook.com/spirent>[X]<https://www.facebook.com/spirent>




Michaelkirchstraße 17/18

10179 Berlin, Germany





+++++  N E W S F L A S H  +++++



Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.




Spirent Communications e-mail confidentiality.
------------------------------------------------------------------------
This e-mail contains confidential and / or privileged information belonging to Spirent Communications plc, its affiliates and / or subsidiaries. If you are not the intended recipient, you are hereby notified that any disclosure, copying, distribution and / or the taking of any action based upon reliance on the contents of this transmission is strictly forbidden. If you have received this message in error please notify the sender by return e-mail and delete it from your system.

Spirent Communications plc
Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.
Tel No. +44 (0) 1293 767676
Fax No. +44 (0) 1293 767677

Registered in England Number 470893
Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.

Or if within the US,

Spirent Communications,
27349 Agoura Road, Calabasas, CA, 91301, USA.
Tel No. 1-818-676- 2300
Reply | Threaded
Open this post in threaded view
|

Re: throwing static exceptions sometimes VERY slow!

David Holmes
Hi,

On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
> Hi,
>
> I am observing a very strange behavior.
>
> In our generated code (due to various reasons I won't go into here unless I have to, but trust me, they are legit), we throw static exceptions for control flow purposes, This seems to work fine and without performance loss most of the time. However, we are observing now that every few seconds, a throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the normal almost non-measurable time).
>
> Update: it seems that the observed behavior was kind of related with some extraneous circumstances (the computer seems to have been more lagged than usual at that point). By now, I can only observe throws that take up to 20 milliseconds (which opposed to the normal time still seems slow).
>
> It does not seem to be GC related, the only idea that I have is the jitter.

What jitter?

> So, my question is. Is this a known (and for some strange reason maybe even accepted) behavior or is this a bug that I should file with Oracle (or you guys).

You really are not giving us anything to go on here. How are you
observing this slowness? Exactly how do you throw? What exactly are you
measuring? What's the execution context, the machine, processors etc etc
etc.

Regards,
David

>
> BR
>
>
> [X]
>
>
>
>
> Dr. Jacob Wieland
>
> Senior Software Engineer
>
> main    +49.30.7261919.34
>
> mobile +49.173.6446443
>
>
> [hidden email]<mailto:[hidden email]>
>
>
> www.spirent.com
>
>
>
>
>
>
>
>
> Follow us on:
>
>
>
>
> Spirent Communications
>
>
> <https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>|<https://twitter.com/Spirent>[X]<https://twitter.com/Spirent>|<https://www.facebook.com/spirent>[X]<https://www.facebook.com/spirent>
>
>
>
>
> Michaelkirchstraße 17/18
>
> 10179 Berlin, Germany
>
>
>
>
>
> +++++  N E W S F L A S H  +++++
>
>
>
> Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.
>
>
>
>
> Spirent Communications e-mail confidentiality.
> ------------------------------------------------------------------------
> This e-mail contains confidential and / or privileged information belonging to Spirent Communications plc, its affiliates and / or subsidiaries. If you are not the intended recipient, you are hereby notified that any disclosure, copying, distribution and / or the taking of any action based upon reliance on the contents of this transmission is strictly forbidden. If you have received this message in error please notify the sender by return e-mail and delete it from your system.
>
> Spirent Communications plc
> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.
> Tel No. +44 (0) 1293 767676
> Fax No. +44 (0) 1293 767677
>
> Registered in England Number 470893
> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.
>
> Or if within the US,
>
> Spirent Communications,
> 27349 Agoura Road, Calabasas, CA, 91301, USA.
> Tel No. 1-818-676- 2300
>
Reply | Threaded
Open this post in threaded view
|

Re: throwing static exceptions sometimes VERY slow!

Vitaly Davidovich
On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]>
wrote:

> Hi,
>
> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
>
>> Hi,
>>
>> I am observing a very strange behavior.
>>
>> In our generated code (due to various reasons I won't go into here unless
>> I have to, but trust me, they are legit), we throw static exceptions for
>> control flow purposes, This seems to work fine and without performance loss
>> most of the time. However, we are observing now that every few seconds, a
>> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the
>> normal almost non-measurable time).
>>
>> Update: it seems that the observed behavior was kind of related with some
>> extraneous circumstances (the computer seems to have been more lagged than
>> usual at that point). By now, I can only observe throws that take up to 20
>> milliseconds (which opposed to the normal time still seems slow).
>>
>> It does not seem to be GC related, the only idea that I have is the
>> jitter.
>>
>
> What jitter?

I'm assuming Jacob is referring to the JIT.  But yes, he needs to provide
more information.

In particular, it would be good to know the following, as David mentioned,
(off the top of my head):
1) JVM cmdline flags
2) Type of exception thrown (with a stacktrace or not)
3) Is the call stack depth about the same during the slow and fast throws?
4) Is the exception thrown frequently or infrequently?
5) Is there -XX:+PrintCompilation output available around the time when the
slowdown is observed


>
> So, my question is. Is this a known (and for some strange reason maybe
>> even accepted) behavior or is this a bug that I should file with Oracle (or
>> you guys).
>>
>
> You really are not giving us anything to go on here. How are you observing
> this slowness? Exactly how do you throw? What exactly are you measuring?
> What's the execution context, the machine, processors etc etc etc.
>
> Regards,
> David
>
>
>
>> BR
>>
>>
>>   [X]
>>
>>
>>
>>
>> Dr. Jacob Wieland
>>
>> Senior Software Engineer
>>
>> main    +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> [hidden email]<mailto:[hidden email]>
>>
>>
>> www.spirent.com
>>
>>
>>
>>
>>
>>
>>
>>
>> Follow us on:
>>
>>
>>
>>
>> Spirent Communications
>>
>>
>>   <https://www.linkedin.com/company/spirent-communications>[X]<
>> https://www.linkedin.com/company/spirent-communications>|  <
>> https://twitter.com/Spirent>[X]<https://twitter.com/Spirent>|  <
>> https://www.facebook.com/spirent>[X]<https://www.facebook.com/spirent>
>>
>>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>>
>>
>> +++++  N E W S F L A S H  +++++
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become
>> your test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>>
>>
>>
>> Spirent Communications e-mail confidentiality.
>> ------------------------------------------------------------------------
>> This e-mail contains confidential and / or privileged information
>> belonging to Spirent Communications plc, its affiliates and / or
>> subsidiaries. If you are not the intended recipient, you are hereby
>> notified that any disclosure, copying, distribution and / or the taking of
>> any action based upon reliance on the contents of this transmission is
>> strictly forbidden. If you have received this message in error please
>> notify the sender by return e-mail and delete it from your system.
>>
>> Spirent Communications plc
>> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
>> Kingdom.
>> Tel No. +44 (0) 1293 767676
>> Fax No. +44 (0) 1293 767677
>>
>> Registered in England Number 470893
>> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
>> 9XN, United Kingdom.
>>
>> Or if within the US,
>>
>> Spirent Communications,
>> 27349 Agoura Road, Calabasas, CA, 91301, USA.
>> Tel No. 1-818-676- 2300
>>
>>
Reply | Threaded
Open this post in threaded view
|

Re: throwing static exceptions sometimes VERY slow!

Wieland, Jacob
Hi,


here are the general system infos:


uname -a:


Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3 (2016-01-17) x86_64 GNU/Linux


lscpu:


Architecture:          x86_64
CPU op-mode(s):        32-bit, 64-bit
Byte Order:            Little Endian
CPU(s):                4
On-line CPU(s) list:   0-3
Thread(s) per core:    1
Core(s) per socket:    4
Socket(s):             1
NUMA node(s):          1
Vendor ID:             GenuineIntel
CPU family:            6
Model:                 58
Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
Stepping:              9
CPU MHz:               2094.558
CPU max MHz:           3500.0000
CPU min MHz:           1600.0000
BogoMIPS:              6186.30
Virtualization:        VT-x
L1d cache:             32K
L1i cache:             32K
L2 cache:              256K
L3 cache:              6144K
NUMA node0 CPU(s):     0-3


java -version:


java version "1.8.0_102"
Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)

Rest of the answers inline.

BR


[X]




Dr. Jacob Wieland

Senior Software Engineer

main    +49.30.7261919.34

mobile +49.173.6446443


[hidden email]<mailto:[hidden email]>


www.spirent.com








Follow us on:




Spirent Communications


<https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>|<https://twitter.com/Spirent>[X]<https://twitter.com/Spirent>|<https://www.facebook.com/spirent>[X]<https://www.facebook.com/spirent>




Michaelkirchstraße 17/18

10179 Berlin, Germany





+++++  N E W S F L A S H  +++++



Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.

________________________________
From: Vitaly Davidovich <[hidden email]>
Sent: Tuesday, February 28, 2017 1:46:09 PM
To: David Holmes
Cc: Wieland, Jacob; [hidden email]
Subject: Re: throwing static exceptions sometimes VERY slow!



On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]<mailto:[hidden email]>> wrote:
Hi,

On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
Hi,

I am observing a very strange behavior.

In our generated code (due to various reasons I won't go into here unless I have to, but trust me, they are legit), we throw static exceptions for control flow purposes, This seems to work fine and without performance loss most of the time. However, we are observing now that every few seconds, a throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the normal almost non-measurable time).

Update: it seems that the observed behavior was kind of related with some extraneous circumstances (the computer seems to have been more lagged than usual at that point). By now, I can only observe throws that take up to 20 milliseconds (which opposed to the normal time still seems slow).

It does not seem to be GC related, the only idea that I have is the jitter.

What jitter?
I'm assuming Jacob is referring to the JIT.  But yes, he needs to provide more information.

In particular, it would be good to know the following, as David mentioned, (off the top of my head):
1) JVM cmdline flags

-Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y

2) Type of exception thrown (with a stacktrace or not)

Exception class derived from java.lang.Error that overrides fillInStackTrace() with 'return this', so stackless. Same instances stored in static final fields are always thrown.

3) Is the call stack depth about the same during the slow and fast throws?

It is always exactly the same stack, as it happens in a loop.

4) Is the exception thrown frequently or infrequently?

In the test where this was observed, the exception was thrown every 40ms, so, I guess, frequently.

5) Is there -XX:+PrintCompilation output available around the time when the slowdown is observed

Unfortunately not, and at the moment, I cannot reproduce the behavior.

I made a mockup-test (see attachment) that mimicks kind of what my generated code does and adds measurements before throw and after catch.
Mostly, in my experiments with this, the throw takes on average 20 ns, but between a 1 and 3 per million iterations take longer than 1 ms, on average around 7 ms. It can be observed that doing a garbage collection in a different java process (namely my eclipse that started the test) greatly influences the frequency of the > 1 ms throws, so maybe it is simply a load issue. Using multiple threads in parallel also seems to heighten the

Also, when introducing an additional sleep between iterations (like in my original scenario where I was waiting for a timer to timeout before executing the construct that used the throw), I cannot reproduce such outliers at all.



So, my question is. Is this a known (and for some strange reason maybe even accepted) behavior or is this a bug that I should file with Oracle (or you guys).

You really are not giving us anything to go on here. How are you observing this slowness? Exactly how do you throw? What exactly are you measuring? What's the execution context, the machine, processors etc etc etc.

I was observing the slowness in a testcase where I wanted regular intervals of 40 ms between sending a message via UDP but frequently (every few seconds) got a lag of around 1.5 seconds (and a few days later 0.5 seconds) before the timer which timed out at the correct time was noted.

When eliminating one kind of such thrown control exception, the next kind of thrown control exception (from a surrounding construct) was having the same effect which actually led me to the slow-throw-hypothesis. Eliminating all exceptions in the small example confirmed this hypothesis, but going that route would take a lot of effort for all cases and introduce other additional imperformances (as I basically have to mock the exception throwing via cascading return and if-checks on every level) which I would like to avoid.

Regards,
David





Spirent Communications e-mail confidentiality.
------------------------------------------------------------------------
This e-mail contains confidential and / or privileged information belonging to Spirent Communications plc, its affiliates and / or subsidiaries. If you are not the intended recipient, you are hereby notified that any disclosure, copying, distribution and / or the taking of any action based upon reliance on the contents of this transmission is strictly forbidden. If you have received this message in error please notify the sender by return e-mail and delete it from your system.

Spirent Communications plc
Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.
Tel No. +44 (0) 1293 767676
Fax No. +44 (0) 1293 767677

Registered in England Number 470893
Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United Kingdom.

Or if within the US,

Spirent Communications,
27349 Agoura Road, Calabasas, CA, 91301, USA.
Tel No. 1-818-676- 2300
Reply | Threaded
Open this post in threaded view
|

Re: Fw: throwing static exceptions sometimes VERY slow!

Vitaly Davidovich
+hotspot dev as it got dropped

On Wed, Mar 1, 2017 at 7:03 PM Vitaly Davidovich <[hidden email]> wrote:

> Instead of overriding fillInStacktrace, which is a synchronized method and
> you're sharing those instances between threads, can you construct the
> Continue and Break exceptions telling base class that you don't want
> writable stacktrace?
>
> The jitter you're seeing could be lock contention due to above, biased
> lock revocation, JIT deoptimizations (although in your Test I'm not sure if
> it'll deoptimize since the throws are not uncommon).
>
> You can add -XX:+PrintSafepointStatistics
> -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed
> to stdout.
>
> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
> doing something.
>
> On Wed, Mar 1, 2017 at 7:52 AM Wieland, Jacob <[hidden email]>
> wrote:
>
>
>
>
> sorry, forgot the attachment
>
>
> BR
>
>
>
> *Dr. Jacob Wieland*
>
> *Senior Software Engineer*
>
> main    +49.30.7261919.34
>
> mobile +49.173.6446443
>
>
> [hidden email]
>
>
> www.spirent.com
>
>
>
>
> Follow us on:
>
>
> Spirent Communications
>
> <https://www.linkedin.com/company/spirent-communications>
> <https://www.linkedin.com/company/spirent-communications>|
> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>
>
> Michaelkirchstraße 17/18
>
> 10179 Berlin, Germany
>
>
>
> *+++++  N E W S F L A S H  +++++*
>
>
>
> Spirent Communications and Testing Technologies join forces to become your
> test automation power-house. Read more at http://conta.cc/1S62BEY.
>
> ------------------------------
> *From:* Wieland, Jacob
> *Sent:* Wednesday, March 1, 2017 1:47:52 PM
> *To:* Vitaly Davidovich; David Holmes
> *Cc:* [hidden email]
>
> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>
> Hi,
>
>
> here are the general system infos:
>
>
> uname -a:
>
>
> Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3
> (2016-01-17) x86_64 GNU/Linux
>
>
> lscpu:
>
>
> Architecture:          x86_64
> CPU op-mode(s):        32-bit, 64-bit
> Byte Order:            Little Endian
> CPU(s):                4
> On-line CPU(s) list:   0-3
> Thread(s) per core:    1
> Core(s) per socket:    4
> Socket(s):             1
> NUMA node(s):          1
> Vendor ID:             GenuineIntel
> CPU family:            6
> Model:                 58
> Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
> Stepping:              9
> CPU MHz:               2094.558
> CPU max MHz:           3500.0000
> CPU min MHz:           1600.0000
> BogoMIPS:              6186.30
> Virtualization:        VT-x
> L1d cache:             32K
> L1i cache:             32K
> L2 cache:              256K
> L3 cache:              6144K
> NUMA node0 CPU(s):     0-3
>
> java -version:
>
>
> java version "1.8.0_102"
> Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
> Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)
>
> Rest of the answers inline.
>
> BR
>
>
>
> *Dr. Jacob Wieland*
>
> *Senior Software Engineer*
>
> main    +49.30.7261919.34
>
> mobile +49.173.6446443
>
>
> [hidden email]
>
>
> www.spirent.com
>
>
>
>
> Follow us on:
>
>
> Spirent Communications
>
> <https://www.linkedin.com/company/spirent-communications>
> <https://www.linkedin.com/company/spirent-communications>|
> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>
>
> Michaelkirchstraße 17/18
>
> 10179 Berlin, Germany
>
>
>
> *+++++  N E W S F L A S H  +++++*
>
>
>
> Spirent Communications and Testing Technologies join forces to become your
> test automation power-house. Read more at http://conta.cc/1S62BEY.
>
> ------------------------------
> *From:* Vitaly Davidovich <[hidden email]>
> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
> *To:* David Holmes
> *Cc:* Wieland, Jacob; [hidden email]
> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>
>
>
> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]>
> wrote:
>
> Hi,
>
> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
>
> Hi,
>
> I am observing a very strange behavior.
>
> In our generated code (due to various reasons I won't go into here unless
> I have to, but trust me, they are legit), we throw static exceptions for
> control flow purposes, This seems to work fine and without performance loss
> most of the time. However, we are observing now that every few seconds, a
> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the
> normal almost non-measurable time).
>
> Update: it seems that the observed behavior was kind of related with some
> extraneous circumstances (the computer seems to have been more lagged than
> usual at that point). By now, I can only observe throws that take up to 20
> milliseconds (which opposed to the normal time still seems slow).
>
> It does not seem to be GC related, the only idea that I have is the jitter.
>
>
> What jitter?
>
> I'm assuming Jacob is referring to the JIT.  But yes, he needs to provide
> more information.
>
> In particular, it would be good to know the following, as David mentioned,
> (off the top of my head):
> 1) JVM cmdline flags
>
> -Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y
>
> 2) Type of exception thrown (with a stacktrace or not)
>
> Exception class derived from java.lang.Error that overrides
> fillInStackTrace() with 'return this', so stackless. Same instances stored
> in static final fields are always thrown.
>
> 3) Is the call stack depth about the same during the slow and fast throws?
>
> It is always exactly the same stack, as it happens in a loop.
>
> 4) Is the exception thrown frequently or infrequently?
>
> In the test where this was observed, the exception was thrown every 40ms,
> so, I guess, frequently.
>
> 5) Is there -XX:+PrintCompilation output available around the time when
> the slowdown is observed
>
> Unfortunately not, and at the moment, I cannot reproduce the behavior.
>
> I made a mockup-test (see attachment) that mimicks kind of what my
> generated code does and adds measurements before throw and after catch.
> Mostly, in my experiments with this, the throw takes on average 20 ns,
> but between a 1 and 3 per million iterations take longer than 1 ms, on
> average around 7 ms. It can be observed that doing a garbage collection in
> a different java process (namely my eclipse that started the test) greatly
> influences the frequency of the > 1 ms throws, so maybe it is simply a load
> issue. Using multiple threads in parallel also seems to heighten the
>
> Also, when introducing an additional sleep between iterations (like in my
> original scenario where I was waiting for a timer to timeout before
> executing the construct that used the throw), I cannot reproduce such
> outliers at all.
>
>
>
> So, my question is. Is this a known (and for some strange reason maybe
> even accepted) behavior or is this a bug that I should file with Oracle (or
> you guys).
>
>
> You really are not giving us anything to go on here. How are you observing
> this slowness? Exactly how do you throw? What exactly are you measuring?
> What's the execution context, the machine, processors etc etc etc.
>
>
> I was observing the slowness in a testcase where I wanted regular
> intervals of 40 ms between sending a message via UDP but frequently (every
> few seconds) got a lag of around 1.5 seconds (and a few days later 0.5
> seconds) before the timer which timed out at the correct time was noted.
>
>
> When eliminating one kind of such thrown control exception, the next kind
> of thrown control exception (from a surrounding construct) was having the
> same effect which actually led me to the slow-throw-hypothesis. Eliminating
> all exceptions in the small example confirmed this hypothesis, but going
> that route would take a lot of effort for all cases and introduce other
> additional imperformances (as I basically have to mock the exception
> throwing via cascading return and if-checks on every level) which I would
> like to avoid.
>
> Regards,
> David
>
>
>
>
>
> Spirent Communications e-mail confidentiality.
> ------------------------------------------------------------------------
> This e-mail contains confidential and / or privileged information
> belonging to Spirent Communications plc, its affiliates and / or
> subsidiaries. If you are not the intended recipient, you are hereby
> notified that any disclosure, copying, distribution and / or the taking of
> any action based upon reliance on the contents of this transmission is
> strictly forbidden. If you have received this message in error please
> notify the sender by return e-mail and delete it from your system.
>
> Spirent Communications plc
> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
> Kingdom.
> Tel No. +44 (0) 1293 767676
> Fax No. +44 (0) 1293 767677
>
> Registered in England Number 470893
> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
> 9XN, United Kingdom.
>
> Or if within the US,
>
> Spirent Communications,
> 27349 Agoura Road, Calabasas, CA, 91301, USA.
> Tel No. 1-818-676- 2300
>
> --
> Sent from my phone
>
--
Sent from my phone
Reply | Threaded
Open this post in threaded view
|

Re: Fw: throwing static exceptions sometimes VERY slow!

Ioi Lam
Vitaly,

Thanks for forwarding the email. Unfortunately, the HTML formatting has
been stripped by the mailing list so it's hard to see who said what :-(

> I made a mockup-test (see attachment) that mimicks kind of what my
> generated code does and adds measurements before throw and after catch.
> Mostly, in my experiments with this, the throw takes on average 20 ns,
> but between a 1 and 3 per million iterations take longer than 1 ms, on
> average around 7 ms. It can be observed that doing a garbage collection in
> a different java process (namely my eclipse that started the test) greatly
> influences the frequency of the > 1 ms throws, so maybe it is simply a load
> issue. Using multiple threads in parallel also seems to heighten the

Perhaps the slow down is caused by GC?

One simple way to try is to run with different heap sizes, and use
different type of collectors. If you observe different frequency of the
outlier cases, then it's probably caused by GC pauses.

Jacob, could you post the mockup test again?

Thanks
- Ioi

On 3/1/17 4:04 PM, Vitaly Davidovich wrote:

> +hotspot dev as it got dropped
>
> On Wed, Mar 1, 2017 at 7:03 PM Vitaly Davidovich <[hidden email]> wrote:
>
>> Instead of overriding fillInStacktrace, which is a synchronized method and
>> you're sharing those instances between threads, can you construct the
>> Continue and Break exceptions telling base class that you don't want
>> writable stacktrace?
>>
>> The jitter you're seeing could be lock contention due to above, biased
>> lock revocation, JIT deoptimizations (although in your Test I'm not sure if
>> it'll deoptimize since the throws are not uncommon).
>>
>> You can add -XX:+PrintSafepointStatistics
>> -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed
>> to stdout.
>>
>> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
>> doing something.
>>
>> On Wed, Mar 1, 2017 at 7:52 AM Wieland, Jacob <[hidden email]>
>> wrote:
>>
>>
>>
>>
>> sorry, forgot the attachment
>>
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> [hidden email]
>>
>>
>> www.spirent.com
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become your
>> test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Wieland, Jacob
>> *Sent:* Wednesday, March 1, 2017 1:47:52 PM
>> *To:* Vitaly Davidovich; David Holmes
>> *Cc:* [hidden email]
>>
>> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>>
>> Hi,
>>
>>
>> here are the general system infos:
>>
>>
>> uname -a:
>>
>>
>> Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3
>> (2016-01-17) x86_64 GNU/Linux
>>
>>
>> lscpu:
>>
>>
>> Architecture:          x86_64
>> CPU op-mode(s):        32-bit, 64-bit
>> Byte Order:            Little Endian
>> CPU(s):                4
>> On-line CPU(s) list:   0-3
>> Thread(s) per core:    1
>> Core(s) per socket:    4
>> Socket(s):             1
>> NUMA node(s):          1
>> Vendor ID:             GenuineIntel
>> CPU family:            6
>> Model:                 58
>> Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
>> Stepping:              9
>> CPU MHz:               2094.558
>> CPU max MHz:           3500.0000
>> CPU min MHz:           1600.0000
>> BogoMIPS:              6186.30
>> Virtualization:        VT-x
>> L1d cache:             32K
>> L1i cache:             32K
>> L2 cache:              256K
>> L3 cache:              6144K
>> NUMA node0 CPU(s):     0-3
>>
>> java -version:
>>
>>
>> java version "1.8.0_102"
>> Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
>> Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)
>>
>> Rest of the answers inline.
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> [hidden email]
>>
>>
>> www.spirent.com
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become your
>> test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Vitaly Davidovich <[hidden email]>
>> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
>> *To:* David Holmes
>> *Cc:* Wieland, Jacob; [hidden email]
>> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>>
>>
>>
>> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]>
>> wrote:
>>
>> Hi,
>>
>> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
>>
>> Hi,
>>
>> I am observing a very strange behavior.
>>
>> In our generated code (due to various reasons I won't go into here unless
>> I have to, but trust me, they are legit), we throw static exceptions for
>> control flow purposes, This seems to work fine and without performance loss
>> most of the time. However, we are observing now that every few seconds, a
>> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the
>> normal almost non-measurable time).
>>
>> Update: it seems that the observed behavior was kind of related with some
>> extraneous circumstances (the computer seems to have been more lagged than
>> usual at that point). By now, I can only observe throws that take up to 20
>> milliseconds (which opposed to the normal time still seems slow).
>>
>> It does not seem to be GC related, the only idea that I have is the jitter.
>>
>>
>> What jitter?
>>
>> I'm assuming Jacob is referring to the JIT.  But yes, he needs to provide
>> more information.
>>
>> In particular, it would be good to know the following, as David mentioned,
>> (off the top of my head):
>> 1) JVM cmdline flags
>>
>> -Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y
>>
>> 2) Type of exception thrown (with a stacktrace or not)
>>
>> Exception class derived from java.lang.Error that overrides
>> fillInStackTrace() with 'return this', so stackless. Same instances stored
>> in static final fields are always thrown.
>>
>> 3) Is the call stack depth about the same during the slow and fast throws?
>>
>> It is always exactly the same stack, as it happens in a loop.
>>
>> 4) Is the exception thrown frequently or infrequently?
>>
>> In the test where this was observed, the exception was thrown every 40ms,
>> so, I guess, frequently.
>>
>> 5) Is there -XX:+PrintCompilation output available around the time when
>> the slowdown is observed
>>
>> Unfortunately not, and at the moment, I cannot reproduce the behavior.
>>
>> I made a mockup-test (see attachment) that mimicks kind of what my
>> generated code does and adds measurements before throw and after catch.
>> Mostly, in my experiments with this, the throw takes on average 20 ns,
>> but between a 1 and 3 per million iterations take longer than 1 ms, on
>> average around 7 ms. It can be observed that doing a garbage collection in
>> a different java process (namely my eclipse that started the test) greatly
>> influences the frequency of the > 1 ms throws, so maybe it is simply a load
>> issue. Using multiple threads in parallel also seems to heighten the
>>
>> Also, when introducing an additional sleep between iterations (like in my
>> original scenario where I was waiting for a timer to timeout before
>> executing the construct that used the throw), I cannot reproduce such
>> outliers at all.
>>
>>
>>
>> So, my question is. Is this a known (and for some strange reason maybe
>> even accepted) behavior or is this a bug that I should file with Oracle (or
>> you guys).
>>
>>
>> You really are not giving us anything to go on here. How are you observing
>> this slowness? Exactly how do you throw? What exactly are you measuring?
>> What's the execution context, the machine, processors etc etc etc.
>>
>>
>> I was observing the slowness in a testcase where I wanted regular
>> intervals of 40 ms between sending a message via UDP but frequently (every
>> few seconds) got a lag of around 1.5 seconds (and a few days later 0.5
>> seconds) before the timer which timed out at the correct time was noted.
>>
>>
>> When eliminating one kind of such thrown control exception, the next kind
>> of thrown control exception (from a surrounding construct) was having the
>> same effect which actually led me to the slow-throw-hypothesis. Eliminating
>> all exceptions in the small example confirmed this hypothesis, but going
>> that route would take a lot of effort for all cases and introduce other
>> additional imperformances (as I basically have to mock the exception
>> throwing via cascading return and if-checks on every level) which I would
>> like to avoid.
>>
>> Regards,
>> David
>>
>>
>>
>>
>>
>> Spirent Communications e-mail confidentiality.
>> ------------------------------------------------------------------------
>> This e-mail contains confidential and / or privileged information
>> belonging to Spirent Communications plc, its affiliates and / or
>> subsidiaries. If you are not the intended recipient, you are hereby
>> notified that any disclosure, copying, distribution and / or the taking of
>> any action based upon reliance on the contents of this transmission is
>> strictly forbidden. If you have received this message in error please
>> notify the sender by return e-mail and delete it from your system.
>>
>> Spirent Communications plc
>> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
>> Kingdom.
>> Tel No. +44 (0) 1293 767676
>> Fax No. +44 (0) 1293 767677
>>
>> Registered in England Number 470893
>> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
>> 9XN, United Kingdom.
>>
>> Or if within the US,
>>
>> Spirent Communications,
>> 27349 Agoura Road, Calabasas, CA, 91301, USA.
>> Tel No. 1-818-676- 2300
>>
>> --
>> Sent from my phone
>>

Reply | Threaded
Open this post in threaded view
|

Re: Fw: throwing static exceptions sometimes VERY slow!

Vitaly Davidovich
Ioi,

Argh, you're right about the formatting.  I'll paste below my last reply to
Jacob.

Instead of overriding fillInStacktrace, which is a synchronized method and
you're sharing those instances between threads, can you construct the
Continue and Break exceptions telling base class that you don't want
writable stacktrace?

The jitter you're seeing could be lock contention due to above, biased lock
revocation, JIT deoptimizations (although in your Test I'm not sure if
it'll deoptimize since the throws are not uncommon).

You can add -XX:+PrintSafepointStatistics
-XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed
to stdout.

As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
doing something.

On Thu, Mar 2, 2017 at 1:12 AM Ioi Lam <[hidden email]> wrote:

> Vitaly,
>
> Thanks for forwarding the email. Unfortunately, the HTML formatting has
> been stripped by the mailing list so it's hard to see who said what :-(
>
> > I made a mockup-test (see attachment) that mimicks kind of what my
> > generated code does and adds measurements before throw and after catch.
> > Mostly, in my experiments with this, the throw takes on average 20 ns,
> > but between a 1 and 3 per million iterations take longer than 1 ms, on
> > average around 7 ms. It can be observed that doing a garbage collection
> in
> > a different java process (namely my eclipse that started the test)
> greatly
> > influences the frequency of the > 1 ms throws, so maybe it is simply a
> load
> > issue. Using multiple threads in parallel also seems to heighten the
>
> Perhaps the slow down is caused by GC?
>
> One simple way to try is to run with different heap sizes, and use
> different type of collectors. If you observe different frequency of the
> outlier cases, then it's probably caused by GC pauses.
>
> Jacob, could you post the mockup test again?
>
> Thanks
> - Ioi
>
> On 3/1/17 4:04 PM, Vitaly Davidovich wrote:
> > +hotspot dev as it got dropped
> >
> > On Wed, Mar 1, 2017 at 7:03 PM Vitaly Davidovich <[hidden email]>
> wrote:
> >
> >> Instead of overriding fillInStacktrace, which is a synchronized method
> and
> >> you're sharing those instances between threads, can you construct the
> >> Continue and Break exceptions telling base class that you don't want
> >> writable stacktrace?
> >>
> >> The jitter you're seeing could be lock contention due to above, biased
> >> lock revocation, JIT deoptimizations (although in your Test I'm not
> sure if
> >> it'll deoptimize since the throws are not uncommon).
> >>
> >> You can add -XX:+PrintSafepointStatistics
> >> -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints
> printed
> >> to stdout.
> >>
> >> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
> >> doing something.
> >>
> >> On Wed, Mar 1, 2017 at 7:52 AM Wieland, Jacob <
> [hidden email]>
> >> wrote:
> >>
> >>
> >>
> >>
> >> sorry, forgot the attachment
> >>
> >>
> >> BR
> >>
> >>
> >>
> >> *Dr. Jacob Wieland*
> >>
> >> *Senior Software Engineer*
> >>
> >> main    +49.30.7261919.34
> >>
> >> mobile +49.173.6446443
> >>
> >>
> >> [hidden email]
> >>
> >>
> >> www.spirent.com
> >>
> >>
> >>
> >>
> >> Follow us on:
> >>
> >>
> >> Spirent Communications
> >>
> >> <https://www.linkedin.com/company/spirent-communications>
> >> <https://www.linkedin.com/company/spirent-communications>|
> >> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
> >> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
> >>
> >>
> >> Michaelkirchstraße 17/18
> >>
> >> 10179 Berlin, Germany
> >>
> >>
> >>
> >> *+++++  N E W S F L A S H  +++++*
> >>
> >>
> >>
> >> Spirent Communications and Testing Technologies join forces to become
> your
> >> test automation power-house. Read more at http://conta.cc/1S62BEY.
> >>
> >> ------------------------------
> >> *From:* Wieland, Jacob
> >> *Sent:* Wednesday, March 1, 2017 1:47:52 PM
> >> *To:* Vitaly Davidovich; David Holmes
> >> *Cc:* [hidden email]
> >>
> >> *Subject:* Re: throwing static exceptions sometimes VERY slow!
> >>
> >> Hi,
> >>
> >>
> >> here are the general system infos:
> >>
> >>
> >> uname -a:
> >>
> >>
> >> Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3
> >> (2016-01-17) x86_64 GNU/Linux
> >>
> >>
> >> lscpu:
> >>
> >>
> >> Architecture:          x86_64
> >> CPU op-mode(s):        32-bit, 64-bit
> >> Byte Order:            Little Endian
> >> CPU(s):                4
> >> On-line CPU(s) list:   0-3
> >> Thread(s) per core:    1
> >> Core(s) per socket:    4
> >> Socket(s):             1
> >> NUMA node(s):          1
> >> Vendor ID:             GenuineIntel
> >> CPU family:            6
> >> Model:                 58
> >> Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
> >> Stepping:              9
> >> CPU MHz:               2094.558
> >> CPU max MHz:           3500.0000
> >> CPU min MHz:           1600.0000
> >> BogoMIPS:              6186.30
> >> Virtualization:        VT-x
> >> L1d cache:             32K
> >> L1i cache:             32K
> >> L2 cache:              256K
> >> L3 cache:              6144K
> >> NUMA node0 CPU(s):     0-3
> >>
> >> java -version:
> >>
> >>
> >> java version "1.8.0_102"
> >> Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
> >> Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)
> >>
> >> Rest of the answers inline.
> >>
> >> BR
> >>
> >>
> >>
> >> *Dr. Jacob Wieland*
> >>
> >> *Senior Software Engineer*
> >>
> >> main    +49.30.7261919.34
> >>
> >> mobile +49.173.6446443
> >>
> >>
> >> [hidden email]
> >>
> >>
> >> www.spirent.com
> >>
> >>
> >>
> >>
> >> Follow us on:
> >>
> >>
> >> Spirent Communications
> >>
> >> <https://www.linkedin.com/company/spirent-communications>
> >> <https://www.linkedin.com/company/spirent-communications>|
> >> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
> >> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
> >>
> >>
> >> Michaelkirchstraße 17/18
> >>
> >> 10179 Berlin, Germany
> >>
> >>
> >>
> >> *+++++  N E W S F L A S H  +++++*
> >>
> >>
> >>
> >> Spirent Communications and Testing Technologies join forces to become
> your
> >> test automation power-house. Read more at http://conta.cc/1S62BEY.
> >>
> >> ------------------------------
> >> *From:* Vitaly Davidovich <[hidden email]>
> >> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
> >> *To:* David Holmes
> >> *Cc:* Wieland, Jacob; [hidden email]
> >> *Subject:* Re: throwing static exceptions sometimes VERY slow!
> >>
> >>
> >>
> >> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]>
> >> wrote:
> >>
> >> Hi,
> >>
> >> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
> >>
> >> Hi,
> >>
> >> I am observing a very strange behavior.
> >>
> >> In our generated code (due to various reasons I won't go into here
> unless
> >> I have to, but trust me, they are legit), we throw static exceptions for
> >> control flow purposes, This seems to work fine and without performance
> loss
> >> most of the time. However, we are observing now that every few seconds,
> a
> >> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to
> the
> >> normal almost non-measurable time).
> >>
> >> Update: it seems that the observed behavior was kind of related with
> some
> >> extraneous circumstances (the computer seems to have been more lagged
> than
> >> usual at that point). By now, I can only observe throws that take up to
> 20
> >> milliseconds (which opposed to the normal time still seems slow).
> >>
> >> It does not seem to be GC related, the only idea that I have is the
> jitter.
> >>
> >>
> >> What jitter?
> >>
> >> I'm assuming Jacob is referring to the JIT.  But yes, he needs to
> provide
> >> more information.
> >>
> >> In particular, it would be good to know the following, as David
> mentioned,
> >> (off the top of my head):
> >> 1) JVM cmdline flags
> >>
> >> -Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y
> >>
> >> 2) Type of exception thrown (with a stacktrace or not)
> >>
> >> Exception class derived from java.lang.Error that overrides
> >> fillInStackTrace() with 'return this', so stackless. Same instances
> stored
> >> in static final fields are always thrown.
> >>
> >> 3) Is the call stack depth about the same during the slow and fast
> throws?
> >>
> >> It is always exactly the same stack, as it happens in a loop.
> >>
> >> 4) Is the exception thrown frequently or infrequently?
> >>
> >> In the test where this was observed, the exception was thrown every
> 40ms,
> >> so, I guess, frequently.
> >>
> >> 5) Is there -XX:+PrintCompilation output available around the time when
> >> the slowdown is observed
> >>
> >> Unfortunately not, and at the moment, I cannot reproduce the behavior.
> >>
> >> I made a mockup-test (see attachment) that mimicks kind of what my
> >> generated code does and adds measurements before throw and after catch.
> >> Mostly, in my experiments with this, the throw takes on average 20 ns,
> >> but between a 1 and 3 per million iterations take longer than 1 ms, on
> >> average around 7 ms. It can be observed that doing a garbage collection
> in
> >> a different java process (namely my eclipse that started the test)
> greatly
> >> influences the frequency of the > 1 ms throws, so maybe it is simply a
> load
> >> issue. Using multiple threads in parallel also seems to heighten the
> >>
> >> Also, when introducing an additional sleep between iterations (like in
> my
> >> original scenario where I was waiting for a timer to timeout before
> >> executing the construct that used the throw), I cannot reproduce such
> >> outliers at all.
> >>
> >>
> >>
> >> So, my question is. Is this a known (and for some strange reason maybe
> >> even accepted) behavior or is this a bug that I should file with Oracle
> (or
> >> you guys).
> >>
> >>
> >> You really are not giving us anything to go on here. How are you
> observing
> >> this slowness? Exactly how do you throw? What exactly are you measuring?
> >> What's the execution context, the machine, processors etc etc etc.
> >>
> >>
> >> I was observing the slowness in a testcase where I wanted regular
> >> intervals of 40 ms between sending a message via UDP but frequently
> (every
> >> few seconds) got a lag of around 1.5 seconds (and a few days later 0.5
> >> seconds) before the timer which timed out at the correct time was noted.
> >>
> >>
> >> When eliminating one kind of such thrown control exception, the next
> kind
> >> of thrown control exception (from a surrounding construct) was having
> the
> >> same effect which actually led me to the slow-throw-hypothesis.
> Eliminating
> >> all exceptions in the small example confirmed this hypothesis, but going
> >> that route would take a lot of effort for all cases and introduce other
> >> additional imperformances (as I basically have to mock the exception
> >> throwing via cascading return and if-checks on every level) which I
> would
> >> like to avoid.
> >>
> >> Regards,
> >> David
> >>
> >>
> >>
> >>
> >>
> >> Spirent Communications e-mail confidentiality.
> >> ------------------------------------------------------------------------
> >> This e-mail contains confidential and / or privileged information
> >> belonging to Spirent Communications plc, its affiliates and / or
> >> subsidiaries. If you are not the intended recipient, you are hereby
> >> notified that any disclosure, copying, distribution and / or the taking
> of
> >> any action based upon reliance on the contents of this transmission is
> >> strictly forbidden. If you have received this message in error please
> >> notify the sender by return e-mail and delete it from your system.
> >>
> >> Spirent Communications plc
> >> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
> >> Kingdom.
> >> Tel No. +44 (0) 1293 767676
> >> Fax No. +44 (0) 1293 767677
> >>
> >> Registered in England Number 470893
> >> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
> >> 9XN, United Kingdom.
> >>
> >> Or if within the US,
> >>
> >> Spirent Communications,
> >> 27349 Agoura Road, Calabasas, CA, 91301, USA.
> >> Tel No. 1-818-676- 2300
> >>
> >> --
> >> Sent from my phone
> >>
>
> --
Sent from my phone
Reply | Threaded
Open this post in threaded view
|

Re: Fw: throwing static exceptions sometimes VERY slow!

Wieland, Jacob
0: loops: 1000000000
     66    1             java.lang.Object::<init> (1 bytes)
     68    2             java.lang.Number::<init> (5 bytes)
     69    3     n       java.lang.System::nanoTime (native)   (static)
     84    4             java.lang.String::indexOf (70 bytes)
     86    5             java.lang.String::hashCode (55 bytes)
0: Thu Mar 02 14:50:41 CET 2017: 178532
     88    6             java.util.concurrent.atomic.AtomicLong::get (5 bytes)
     88    8     n       sun.misc.Unsafe::compareAndSwapLong (native)
     88    7             java.util.concurrent.atomic.AtomicLong::compareAndSet (13 bytes)
     88    9             java.util.Random::next (47 bytes)
     88   10             java.math.BigInteger::add (178 bytes)
     97   11             java.math.BigInteger::valueOf (62 bytes)
     97   12             java.math.BigInteger::<init> (77 bytes)
     98   13             java.math.BigInteger::<init> (24 bytes)
     98   14             java.math.BigInteger::add (123 bytes)
     98   15             java.lang.Math::random (17 bytes)
     99   16             java.util.Random::nextDouble (24 bytes)
    101   17 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ 70 (549 bytes)
    123   17 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ -2 (549 bytes)   made not entrant
    124   18 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ 70 (549 bytes)
   8802   18 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ -2 (549 bytes)   made not entrant
0: Thu Mar 02 14:50:50 CET 2017: 620776
   8803   19 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ 70 (549 bytes)
0: Thu Mar 02 14:50:56 CET 2017: 128566
  21909   19 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ -2 (549 bytes)   made not entrant
  21909   14             java.math.BigInteger::add (123 bytes)   made not entrant
  21909   10             java.math.BigInteger::add (178 bytes)   made not entrant
  21911   20 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ 70 (549 bytes)
  21914   21             java.math.BigInteger::add (178 bytes)
  21921   22             java.math.BigInteger::add (123 bytes)
0: Thu Mar 02 14:51:04 CET 2017: 2974443
0: Thu Mar 02 14:51:05 CET 2017: 103290
  44839   20 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ -2 (549 bytes)   made not entrant
  44840   23 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ 70 (549 bytes)
0: Thu Mar 02 14:51:35 CET 2017: 2076623
0: Thu Mar 02 14:51:36 CET 2017: 333400
0: Thu Mar 02 14:51:37 CET 2017: 240985
0: Thu Mar 02 14:51:39 CET 2017: 1360262
0: Thu Mar 02 14:51:40 CET 2017: 2993867
0: Thu Mar 02 14:51:48 CET 2017: 794752
  67360   22             java.math.BigInteger::add (123 bytes)   made not entrant
  67362   24             java.math.BigInteger::add (123 bytes)
0: Thu Mar 02 14:52:03 CET 2017: 146861
0: Thu Mar 02 14:52:14 CET 2017: 312026
0: Thu Mar 02 14:52:23 CET 2017: 353730
 104327   23 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure @ -2 (549 bytes)   made not entrant
 104327   11             java.math.BigInteger::valueOf (62 bytes)   made not entrant
0: longThrows: 14 average time: 901293
0: shortThrows: 999999986 average time: 19
0: sum: 19999665505
0: average throw time: 19

That was run using nice -19 to minimize interaction with other processes.


BR


[X]




Dr. Jacob Wieland

Senior Software Engineer

main    +49.30.7261919.34

mobile +49.173.6446443


[hidden email]<mailto:[hidden email]>


www.spirent.com








Follow us on:




Spirent Communications


<https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>|<https://twitter.com/Spirent>[X]<https://twitter.com/Spirent>|<https://www.facebook.com/spirent>[X]<https://www.facebook.com/spirent>




Michaelkirchstraße 17/18

10179 Berlin, Germany





+++++  N E W S F L A S H  +++++



Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.

________________________________
From: Vitaly Davidovich <[hidden email]>
Sent: Thursday, March 2, 2017 2:45:15 PM
To: Wieland, Jacob
Cc: Ioi Lam; [hidden email]
Subject: Re: Fw: throwing static exceptions sometimes VERY slow!

That's the safepoint stats, which is good to see - looks like a lot of GC activity.  Is that also the case for your real application? GC activity like that could cause jitter but you mentioned in your original email that you ruled it out somehow?

But, I was asking to see the PrintCompilation output in my last email :).  There's no Deoptimize safepoint entry in the safepoint log here, but would still be interesting to see JITs compilation log.

On Thu, Mar 2, 2017 at 8:36 AM Wieland, Jacob <[hidden email]<mailto:[hidden email]>> wrote:


here you are


BR


[X]




Dr. Jacob Wieland

Senior Software Engineer

main    +49.30.7261919.34

mobile +49.173.6446443


[hidden email]<mailto:[hidden email]>


www.spirent.com<http://ww.spirent.com>








Follow us on:




Spirent Communications


<https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>| <https://twitter.com/Spirent> [X] <https://twitter.com/Spirent> | <https://www.facebook.com/spirent> [X] <https://www.facebook.com/spirent>




Michaelkirchstraße 17/18

10179 Berlin, Germany





+++++  N E W S F L A S H  +++++



Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.

________________________________
From: Vitaly Davidovich <[hidden email]<mailto:[hidden email]>>
Sent: Thursday, March 2, 2017 1:45:43 PM
To: Wieland, Jacob
Cc: Ioi Lam; [hidden email]<mailto:[hidden email]>

Subject: Re: Fw: throwing static exceptions sometimes VERY slow!
So how about PrintCompilation output?

On Thu, Mar 2, 2017 at 7:31 AM, Wieland, Jacob <[hidden email]<mailto:[hidden email]>> wrote:

I have modified the exception to not writable and disallow supression, but as I would have expected, no change in behavior was observed. Also, if only one thread is running and lock contention was an issue, should that not go away in that case (it doesn't). The other question if have regarding this is: if the exception is static, should fillInStackTrace() not be called only when creating that way before it is actually thrown? Why would that have any influence on the later throw?


If it was just garbage collection, I would assume the GC output (if turned on) happening close to the long-throw output (it doesn't, as far as I can see).


The most interesting observation about this (imho) is that the number of cases seems to be very reproducible, even over different threads, so there seems to be some non-random relationship (which of course could still be related to the underlying platform doing stuff at regular intervals or sth). Maybe I should measure also the distance between the long throws and see whether they are happening regularly or in clumps.


My next experiment will be if the same behavior can be observed with a normal fast operation, but I doubt that as well, because then eliminating the throws from the original example where I observed this first should not have had any positive effect.


Of course, another candidate could also be the System.nanoTime() itself which for some reason might contend on the system level for resources sometimes, but I have no idea how to measure that! [??]


BR


[X]




Dr. Jacob Wieland

Senior Software Engineer

main    +49.30.7261919.34

mobile +49.173.6446443


[hidden email]<mailto:[hidden email]>


www.spirent.com<http://ww.spirent.com>








Follow us on:




Spirent Communications


<https://www.linkedin.com/company/spirent-communications>[X]<https://www.linkedin.com/company/spirent-communications>| <https://twitter.com/Spirent> [X] <https://twitter.com/Spirent> | <https://www.facebook.com/spirent> [X] <https://www.facebook.com/spirent>




Michaelkirchstraße 17/18

10179 Berlin, Germany





+++++  N E W S F L A S H  +++++



Spirent Communications and Testing Technologies join forces to become your test automation power-house. Read more at http://conta.cc/1S62BEY.

________________________________
From: Vitaly Davidovich <[hidden email]<mailto:[hidden email]>>
Sent: Thursday, March 2, 2017 12:35:20 PM
To: Ioi Lam; Wieland, Jacob; [hidden email]<mailto:[hidden email]>
Subject: Re: Fw: throwing static exceptions sometimes VERY slow!

Ioi,

Argh, you're right about the formatting.  I'll paste below my last reply to Jacob.

Instead of overriding fillInStacktrace, which is a synchronized method and you're sharing those instances between threads, can you construct the Continue and Break exceptions telling base class that you don't want writable stacktrace?

The jitter you're seeing could be lock contention due to above, biased lock revocation, JIT deoptimizations (although in your Test I'm not sure if it'll deoptimize since the throws are not uncommon).

You can add -XX:+PrintSafepointStatistics -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed to stdout.

As mentioned, run your test with -XX:+PrintCompilation to see if JIT is doing something.

On Thu, Mar 2, 2017 at 1:12 AM Ioi Lam <[hidden email]<mailto:[hidden email]>> wrote:
Vitaly,

Thanks for forwarding the email. Unfortunately, the HTML formatting has
been stripped by the mailing list so it's hard to see who said what :-(

> I made a mockup-test (see attachment) that mimicks kind of what my
> generated code does and adds measurements before throw and after catch.
> Mostly, in my experiments with this, the throw takes on average 20 ns,
> but between a 1 and 3 per million iterations take longer than 1 ms, on
> average around 7 ms. It can be observed that doing a garbage collection in
> a different java process (namely my eclipse that started the test) greatly
> influences the frequency of the > 1 ms throws, so maybe it is simply a load
> issue. Using multiple threads in parallel also seems to heighten the

Perhaps the slow down is caused by GC?

One simple way to try is to run with different heap sizes, and use
different type of collectors. If you observe different frequency of the
outlier cases, then it's probably caused by GC pauses.

Jacob, could you post the mockup test again?

Thanks
- Ioi

On 3/1/17 4:04 PM, Vitaly Davidovich wrote:

> +hotspot dev as it got dropped
>
> On Wed, Mar 1, 2017 at 7:03 PM Vitaly Davidovich <[hidden email]<mailto:[hidden email]>> wrote:
>
>> Instead of overriding fillInStacktrace, which is a synchronized method and
>> you're sharing those instances between threads, can you construct the
>> Continue and Break exceptions telling base class that you don't want
>> writable stacktrace?
>>
>> The jitter you're seeing could be lock contention due to above, biased
>> lock revocation, JIT deoptimizations (although in your Test I'm not sure if
>> it'll deoptimize since the throws are not uncommon).
>>
>> You can add -XX:+PrintSafepointStatistics
>> -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed
>> to stdout.
>>
>> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
>> doing something.
>>
>> On Wed, Mar 1, 2017 at 7:52 AM Wieland, Jacob <[hidden email]<mailto:[hidden email]>>
>> wrote:
>>
>>
>>
>>
>> sorry, forgot the attachment
>>
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34<tel:+49%2030%20726191934>
>>
>> mobile +49.173.6446443<tel:+49%20173%206446443>
>>
>>
>> [hidden email]<mailto:[hidden email]>
>>
>>
>> www.spirent.com<http://www.spirent.com>
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become your
>> test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Wieland, Jacob
>> *Sent:* Wednesday, March 1, 2017 1:47:52 PM
>> *To:* Vitaly Davidovich; David Holmes
>> *Cc:* [hidden email]<mailto:[hidden email]>
>>
>> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>>
>> Hi,
>>
>>
>> here are the general system infos:
>>
>>
>> uname -a:
>>
>>
>> Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3
>> (2016-01-17) x86_64 GNU/Linux
>>
>>
>> lscpu:
>>
>>
>> Architecture:          x86_64
>> CPU op-mode(s):        32-bit, 64-bit
>> Byte Order:            Little Endian
>> CPU(s):                4
>> On-line CPU(s) list:   0-3
>> Thread(s) per core:    1
>> Core(s) per socket:    4
>> Socket(s):             1
>> NUMA node(s):          1
>> Vendor ID:             GenuineIntel
>> CPU family:            6
>> Model:                 58
>> Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
>> Stepping:              9
>> CPU MHz:               2094.558
>> CPU max MHz:           3500.0000
>> CPU min MHz:           1600.0000
>> BogoMIPS:              6186.30
>> Virtualization:        VT-x
>> L1d cache:             32K
>> L1i cache:             32K
>> L2 cache:              256K
>> L3 cache:              6144K
>> NUMA node0 CPU(s):     0-3
>>
>> java -version:
>>
>>
>> java version "1.8.0_102"
>> Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
>> Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)
>>
>> Rest of the answers inline.
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34<tel:+49%2030%20726191934>
>>
>> mobile +49.173.6446443<tel:+49%20173%206446443>
>>
>>
>> [hidden email]<mailto:[hidden email]>
>>
>>
>> www.spirent.com<http://www.spirent.com>
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become your
>> test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Vitaly Davidovich <[hidden email]<mailto:[hidden email]>>
>> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
>> *To:* David Holmes
>> *Cc:* Wieland, Jacob; [hidden email]<mailto:[hidden email]>
>> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>>
>>
>>
>> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]<mailto:[hidden email]>>
>> wrote:
>>
>> Hi,
>>
>> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
>>
>> Hi,
>>
>> I am observing a very strange behavior.
>>
>> In our generated code (due to various reasons I won't go into here unless
>> I have to, but trust me, they are legit), we throw static exceptions for
>> control flow purposes, This seems to work fine and without performance loss
>> most of the time. However, we are observing now that every few seconds, a
>> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to the
>> normal almost non-measurable time).
>>
>> Update: it seems that the observed behavior was kind of related with some
>> extraneous circumstances (the computer seems to have been more lagged than
>> usual at that point). By now, I can only observe throws that take up to 20
>> milliseconds (which opposed to the normal time still seems slow).
>>
>> It does not seem to be GC related, the only idea that I have is the jitter.
>>
>>
>> What jitter?
>>
>> I'm assuming Jacob is referring to the JIT.  But yes, he needs to provide
>> more information.
>>
>> In particular, it would be good to know the following, as David mentioned,
>> (off the top of my head):
>> 1) JVM cmdline flags
>>
>> -Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y
>>
>> 2) Type of exception thrown (with a stacktrace or not)
>>
>> Exception class derived from java.lang.Error that overrides
>> fillInStackTrace() with 'return this', so stackless. Same instances stored
>> in static final fields are always thrown.
>>
>> 3) Is the call stack depth about the same during the slow and fast throws?
>>
>> It is always exactly the same stack, as it happens in a loop.
>>
>> 4) Is the exception thrown frequently or infrequently?
>>
>> In the test where this was observed, the exception was thrown every 40ms,
>> so, I guess, frequently.
>>
>> 5) Is there -XX:+PrintCompilation output available around the time when
>> the slowdown is observed
>>
>> Unfortunately not, and at the moment, I cannot reproduce the behavior.
>>
>> I made a mockup-test (see attachment) that mimicks kind of what my
>> generated code does and adds measurements before throw and after catch.
>> Mostly, in my experiments with this, the throw takes on average 20 ns,
>> but between a 1 and 3 per million iterations take longer than 1 ms, on
>> average around 7 ms. It can be observed that doing a garbage collection in
>> a different java process (namely my eclipse that started the test) greatly
>> influences the frequency of the > 1 ms throws, so maybe it is simply a load
>> issue. Using multiple threads in parallel also seems to heighten the
>>
>> Also, when introducing an additional sleep between iterations (like in my
>> original scenario where I was waiting for a timer to timeout before
>> executing the construct that used the throw), I cannot reproduce such
>> outliers at all.
>>
>>
>>
>> So, my question is. Is this a known (and for some strange reason maybe
>> even accepted) behavior or is this a bug that I should file with Oracle (or
>> you guys).
>>
>>
>> You really are not giving us anything to go on here. How are you observing
>> this slowness? Exactly how do you throw? What exactly are you measuring?
>> What's the execution context, the machine, processors etc etc etc.
>>
>>
>> I was observing the slowness in a testcase where I wanted regular
>> intervals of 40 ms between sending a message via UDP but frequently (every
>> few seconds) got a lag of around 1.5 seconds (and a few days later 0.5
>> seconds) before the timer which timed out at the correct time was noted.
>>
>>
>> When eliminating one kind of such thrown control exception, the next kind
>> of thrown control exception (from a surrounding construct) was having the
>> same effect which actually led me to the slow-throw-hypothesis. Eliminating
>> all exceptions in the small example confirmed this hypothesis, but going
>> that route would take a lot of effort for all cases and introduce other
>> additional imperformances (as I basically have to mock the exception
>> throwing via cascading return and if-checks on every level) which I would
>> like to avoid.
>>
>> Regards,
>> David
>>
>>
>>
>>
>>
>> Spirent Communications e-mail confidentiality.
>> ------------------------------------------------------------------------
>> This e-mail contains confidential and / or privileged information
>> belonging to Spirent Communications plc, its affiliates and / or
>> subsidiaries. If you are not the intended recipient, you are hereby
>> notified that any disclosure, copying, distribution and / or the taking of
>> any action based upon reliance on the contents of this transmission is
>> strictly forbidden. If you have received this message in error please
>> notify the sender by return e-mail and delete it from your system.
>>
>> Spirent Communications plc
>> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
>> Kingdom.
>> Tel No. +44 (0) 1293 767676<tel:+44%201293%20767676>
>> Fax No. +44 (0) 1293 767677<tel:+44%201293%20767677>
>>
>> Registered in England Number 470893
>> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
>> 9XN, United Kingdom.
>>
>> Or if within the US,
>>
>> Spirent Communications,
>> 27349 Agoura Road, Calabasas, CA, 91301, USA.
>> Tel No. 1-818-676- 2300<tel:(818)%20676-2300>
>>
>> --
>> Sent from my phone
>>

--
Sent from my phone

--
Sent from my phone
Reply | Threaded
Open this post in threaded view
|

Re: Fw: throwing static exceptions sometimes VERY slow!

Vitaly Davidovich
Thanks.  I now realize the compilation output was in your previous
attachment as well, but I was looking at it on my phone and all I could see
was the storm of allocation failures :).

Can you try running your benchmark without using BigInteger (plain long)?
It's creating GC/alloc noise, which would be good to remove from the
equation.

On Thu, Mar 2, 2017 at 8:54 AM, Wieland, Jacob <[hidden email]>
wrote:

> 0: loops: 1000000000
>      66    1             java.lang.Object::<init> (1 bytes)
>      68    2             java.lang.Number::<init> (5 bytes)
>      69    3     n       java.lang.System::nanoTime (native)   (static)
>      84    4             java.lang.String::indexOf (70 bytes)
>      86    5             java.lang.String::hashCode (55 bytes)
> 0: Thu Mar 02 14:50:41 CET 2017: 178532
>      88    6             java.util.concurrent.atomic.AtomicLong::get (5
> bytes)
>      88    8     n       sun.misc.Unsafe::compareAndSwapLong (native)
>      88    7             java.util.concurrent.atomic.AtomicLong::compareAndSet
> (13 bytes)
>      88    9             java.util.Random::next (47 bytes)
>      88   10             java.math.BigInteger::add (178 bytes)
>      97   11             java.math.BigInteger::valueOf (62 bytes)
>      97   12             java.math.BigInteger::<init> (77 bytes)
>      98   13             java.math.BigInteger::<init> (24 bytes)
>      98   14             java.math.BigInteger::add (123 bytes)
>      98   15             java.lang.Math::random (17 bytes)
>      99   16             java.util.Random::nextDouble (24 bytes)
>     101   17 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ 70 (549 bytes)
>     123   17 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ -2 (549 bytes)   made not entrant
>     124   18 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ 70 (549 bytes)
>    8802   18 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ -2 (549 bytes)   made not entrant
> 0: Thu Mar 02 14:50:50 CET 2017: 620776
>    8803   19 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ 70 (549 bytes)
> 0: Thu Mar 02 14:50:56 CET 2017: 128566
>   21909   19 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ -2 (549 bytes)   made not entrant
>   21909   14             java.math.BigInteger::add (123 bytes)   made not
> entrant
>   21909   10             java.math.BigInteger::add (178 bytes)   made not
> entrant
>   21911   20 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ 70 (549 bytes)
>   21914   21             java.math.BigInteger::add (178 bytes)
>   21921   22             java.math.BigInteger::add (123 bytes)
> 0: Thu Mar 02 14:51:04 CET 2017: 2974443
> 0: Thu Mar 02 14:51:05 CET 2017: 103290
>   44839   20 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ -2 (549 bytes)   made not entrant
>   44840   23 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ 70 (549 bytes)
> 0: Thu Mar 02 14:51:35 CET 2017: 2076623
> 0: Thu Mar 02 14:51:36 CET 2017: 333400
> 0: Thu Mar 02 14:51:37 CET 2017: 240985
> 0: Thu Mar 02 14:51:39 CET 2017: 1360262
> 0: Thu Mar 02 14:51:40 CET 2017: 2993867
> 0: Thu Mar 02 14:51:48 CET 2017: 794752
>   67360   22             java.math.BigInteger::add (123 bytes)   made not
> entrant
>   67362   24             java.math.BigInteger::add (123 bytes)
> 0: Thu Mar 02 14:52:03 CET 2017: 146861
> 0: Thu Mar 02 14:52:14 CET 2017: 312026
> 0: Thu Mar 02 14:52:23 CET 2017: 353730
>  104327   23 % !         de.tu_berlin.cs.uebb.muttcn.runtime.Test::measure
> @ -2 (549 bytes)   made not entrant
>  104327   11             java.math.BigInteger::valueOf (62 bytes)   made
> not entrant
> 0: longThrows: 14 average time: 901293
> 0: shortThrows: 999999986 average time: 19
> 0: sum: 19999665505
> 0: average throw time: 19
>
> That was run using nice -19 to minimize interaction with other processes.
>
>
> BR
>
>
>
> *Dr. Jacob Wieland*
>
> *Senior Software Engineer*
>
> main    +49.30.7261919.34
>
> mobile +49.173.6446443
>
>
> [hidden email]
>
>
> www.spirent.com
>
>
>
>
> Follow us on:
>
>
> Spirent Communications
>
> <https://www.linkedin.com/company/spirent-communications>
> <https://www.linkedin.com/company/spirent-communications>|
> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>
>
> Michaelkirchstraße 17/18
>
> 10179 Berlin, Germany
>
>
>
> *+++++  N E W S F L A S H  +++++*
>
>
>
> Spirent Communications and Testing Technologies join forces to become your
> test automation power-house. Read more at http://conta.cc/1S62BEY.
>
> ------------------------------
> *From:* Vitaly Davidovich <[hidden email]>
> *Sent:* Thursday, March 2, 2017 2:45:15 PM
>
> *To:* Wieland, Jacob
> *Cc:* Ioi Lam; [hidden email]
> *Subject:* Re: Fw: throwing static exceptions sometimes VERY slow!
>
> That's the safepoint stats, which is good to see - looks like a lot of GC
> activity.  Is that also the case for your real application? GC activity
> like that could cause jitter but you mentioned in your original email that
> you ruled it out somehow?
>
> But, I was asking to see the PrintCompilation output in my last email :).
> There's no Deoptimize safepoint entry in the safepoint log here, but would
> still be interesting to see JITs compilation log.
>
> On Thu, Mar 2, 2017 at 8:36 AM Wieland, Jacob <[hidden email]>
> wrote:
>
>>
>> here you are
>>
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> [hidden email]
>>
>>
>> www.spirent.com
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become
>> your test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Vitaly Davidovich <[hidden email]>
>> *Sent:* Thursday, March 2, 2017 1:45:43 PM
>> *To:* Wieland, Jacob
>> *Cc:* Ioi Lam; [hidden email]
>>
>> *Subject:* Re: Fw: throwing static exceptions sometimes VERY slow!
>> So how about PrintCompilation output?
>>
>> On Thu, Mar 2, 2017 at 7:31 AM, Wieland, Jacob <[hidden email]
>> > wrote:
>>
>> I have modified the exception to not writable and disallow supression,
>> but as I would have expected, no change in behavior was observed. Also, if
>> only one thread is running and lock contention was an issue, should that
>> not go away in that case (it doesn't). The other question if have regarding
>> this is: if the exception is static, should fillInStackTrace() not be
>> called only when creating that way before it is actually thrown? Why would
>> that have any influence on the later throw?
>>
>>
>> If it was just garbage collection, I would assume the GC output (if
>> turned on) happening close to the long-throw output (it doesn't, as far as
>> I can see).
>>
>>
>> The most interesting observation about this (imho) is that the number of
>> cases seems to be very reproducible, even over different threads, so there
>> seems to be some non-random relationship (which of course could still be
>> related to the underlying platform doing stuff at regular intervals or
>> sth). Maybe I should measure also the distance between the long throws and
>> see whether they are happening regularly or in clumps.
>>
>>
>> My next experiment will be if the same behavior can be observed with a
>> normal fast operation, but I doubt that as well, because then eliminating
>> the throws from the original example where I observed this first should not
>> have had any positive effect.
>>
>>
>> Of course, another candidate could also be the System.nanoTime() itself
>> which for some reason might contend on the system level for resources
>> sometimes, but I have no idea how to measure that! [image: 😉]
>>
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main    +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> [hidden email]
>>
>>
>> www.spirent.com
>>
>>
>>
>>
>> Follow us on:
>>
>>
>> Spirent Communications
>>
>> <https://www.linkedin.com/company/spirent-communications>
>> <https://www.linkedin.com/company/spirent-communications>|
>> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>>
>>
>> Michaelkirchstraße 17/18
>>
>> 10179 Berlin, Germany
>>
>>
>>
>> *+++++  N E W S F L A S H  +++++*
>>
>>
>>
>> Spirent Communications and Testing Technologies join forces to become
>> your test automation power-house. Read more at http://conta.cc/1S62BEY.
>>
>> ------------------------------
>> *From:* Vitaly Davidovich <[hidden email]>
>> *Sent:* Thursday, March 2, 2017 12:35:20 PM
>> *To:* Ioi Lam; Wieland, Jacob; [hidden email]
>> *Subject:* Re: Fw: throwing static exceptions sometimes VERY slow!
>>
>> Ioi,
>>
>> Argh, you're right about the formatting.  I'll paste below my last reply
>> to Jacob.
>>
>> Instead of overriding fillInStacktrace, which is a synchronized method
>> and you're sharing those instances between threads, can you construct the
>> Continue and Break exceptions telling base class that you don't want
>> writable stacktrace?
>>
>> The jitter you're seeing could be lock contention due to above, biased
>> lock revocation, JIT deoptimizations (although in your Test I'm not sure if
>> it'll deoptimize since the throws are not uncommon).
>>
>> You can add -XX:+PrintSafepointStatistics -XX:
>> PrintSafepointStatisticsCount=1 to get reasons for  safepoints printed
>> to stdout.
>>
>> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
>> doing something.
>>
>> On Thu, Mar 2, 2017 at 1:12 AM Ioi Lam <[hidden email]> wrote:
>>
>> Vitaly,
>>
>> Thanks for forwarding the email. Unfortunately, the HTML formatting has
>> been stripped by the mailing list so it's hard to see who said what :-(
>>
>> > I made a mockup-test (see attachment) that mimicks kind of what my
>> > generated code does and adds measurements before throw and after catch.
>> > Mostly, in my experiments with this, the throw takes on average 20 ns,
>> > but between a 1 and 3 per million iterations take longer than 1 ms, on
>> > average around 7 ms. It can be observed that doing a garbage collection
>> in
>> > a different java process (namely my eclipse that started the test)
>> greatly
>> > influences the frequency of the > 1 ms throws, so maybe it is simply a
>> load
>> > issue. Using multiple threads in parallel also seems to heighten the
>>
>> Perhaps the slow down is caused by GC?
>>
>> One simple way to try is to run with different heap sizes, and use
>> different type of collectors. If you observe different frequency of the
>> outlier cases, then it's probably caused by GC pauses.
>>
>> Jacob, could you post the mockup test again?
>>
>> Thanks
>> - Ioi
>>
>> On 3/1/17 4:04 PM, Vitaly Davidovich wrote:
>> > +hotspot dev as it got dropped
>> >
>> > On Wed, Mar 1, 2017 at 7:03 PM Vitaly Davidovich <[hidden email]>
>> wrote:
>> >
>> >> Instead of overriding fillInStacktrace, which is a synchronized method
>> and
>> >> you're sharing those instances between threads, can you construct the
>> >> Continue and Break exceptions telling base class that you don't want
>> >> writable stacktrace?
>> >>
>> >> The jitter you're seeing could be lock contention due to above, biased
>> >> lock revocation, JIT deoptimizations (although in your Test I'm not
>> sure if
>> >> it'll deoptimize since the throws are not uncommon).
>> >>
>> >> You can add -XX:+PrintSafepointStatistics
>> >> -XX:PrintSafepointStatisticsCount=1 to get reasons for  safepoints
>> printed
>> >> to stdout.
>> >>
>> >> As mentioned, run your test with -XX:+PrintCompilation to see if JIT is
>> >> doing something.
>> >>
>> >> On Wed, Mar 1, 2017 at 7:52 AM Wieland, Jacob <
>> [hidden email]>
>> >> wrote:
>> >>
>> >>
>> >>
>> >>
>> >> sorry, forgot the attachment
>> >>
>> >>
>> >> BR
>> >>
>> >>
>> >>
>> >> *Dr. Jacob Wieland*
>> >>
>> >> *Senior Software Engineer*
>> >>
>> >> main    +49.30.7261919.34 <+49%2030%20726191934>
>> >>
>> >> mobile +49.173.6446443 <+49%20173%206446443>
>> >>
>> >>
>> >> [hidden email]
>> >>
>> >>
>> >> www.spirent.com
>> >>
>> >>
>> >>
>> >>
>> >> Follow us on:
>> >>
>> >>
>> >> Spirent Communications
>> >>
>> >> <https://www.linkedin.com/company/spirent-communications>
>> >> <https://www.linkedin.com/company/spirent-communications>|
>> >> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> >> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>> >>
>> >>
>> >> Michaelkirchstraße 17/18
>> >>
>> >> 10179 Berlin, Germany
>> >>
>> >>
>> >>
>> >> *+++++  N E W S F L A S H  +++++*
>> >>
>> >>
>> >>
>> >> Spirent Communications and Testing Technologies join forces to become
>> your
>> >> test automation power-house. Read more at http://conta.cc/1S62BEY.
>> >>
>> >> ------------------------------
>> >> *From:* Wieland, Jacob
>> >> *Sent:* Wednesday, March 1, 2017 1:47:52 PM
>> >> *To:* Vitaly Davidovich; David Holmes
>> >> *Cc:* [hidden email]
>> >>
>> >> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>> >>
>> >> Hi,
>> >>
>> >>
>> >> here are the general system infos:
>> >>
>> >>
>> >> uname -a:
>> >>
>> >>
>> >> Linux ber-28753 3.16.0-4-amd64 #1 SMP Debian 3.16.7-ckt20-1+deb8u3
>> >> (2016-01-17) x86_64 GNU/Linux
>> >>
>> >>
>> >> lscpu:
>> >>
>> >>
>> >> Architecture:          x86_64
>> >> CPU op-mode(s):        32-bit, 64-bit
>> >> Byte Order:            Little Endian
>> >> CPU(s):                4
>> >> On-line CPU(s) list:   0-3
>> >> Thread(s) per core:    1
>> >> Core(s) per socket:    4
>> >> Socket(s):             1
>> >> NUMA node(s):          1
>> >> Vendor ID:             GenuineIntel
>> >> CPU family:            6
>> >> Model:                 58
>> >> Model name:            Intel(R) Core(TM) i5-3450 CPU @ 3.10GHz
>> >> Stepping:              9
>> >> CPU MHz:               2094.558
>> >> CPU max MHz:           3500.0000
>> >> CPU min MHz:           1600.0000
>> >> BogoMIPS:              6186.30
>> >> Virtualization:        VT-x
>> >> L1d cache:             32K
>> >> L1i cache:             32K
>> >> L2 cache:              256K
>> >> L3 cache:              6144K
>> >> NUMA node0 CPU(s):     0-3
>> >>
>> >> java -version:
>> >>
>> >>
>> >> java version "1.8.0_102"
>> >> Java(TM) SE Runtime Environment (build 1.8.0_102-b14)
>> >> Java HotSpot(TM) 64-Bit Server VM (build 25.102-b14, mixed mode)
>> >>
>> >> Rest of the answers inline.
>> >>
>> >> BR
>> >>
>> >>
>> >>
>> >> *Dr. Jacob Wieland*
>> >>
>> >> *Senior Software Engineer*
>> >>
>> >> main    +49.30.7261919.34 <+49%2030%20726191934>
>> >>
>> >> mobile +49.173.6446443 <+49%20173%206446443>
>> >>
>> >>
>> >> [hidden email]
>> >>
>> >>
>> >> www.spirent.com
>> >>
>> >>
>> >>
>> >>
>> >> Follow us on:
>> >>
>> >>
>> >> Spirent Communications
>> >>
>> >> <https://www.linkedin.com/company/spirent-communications>
>> >> <https://www.linkedin.com/company/spirent-communications>|
>> >> <https://twitter.com/Spirent> <https://twitter.com/Spirent>|
>> >> <https://www.facebook.com/spirent> <https://www.facebook.com/spirent>
>> >>
>> >>
>> >> Michaelkirchstraße 17/18
>> >>
>> >> 10179 Berlin, Germany
>> >>
>> >>
>> >>
>> >> *+++++  N E W S F L A S H  +++++*
>> >>
>> >>
>> >>
>> >> Spirent Communications and Testing Technologies join forces to become
>> your
>> >> test automation power-house. Read more at http://conta.cc/1S62BEY.
>> >>
>> >> ------------------------------
>> >> *From:* Vitaly Davidovich <[hidden email]>
>> >> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
>> >> *To:* David Holmes
>> >> *Cc:* Wieland, Jacob; [hidden email]
>> >> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>> >>
>> >>
>> >>
>> >> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <[hidden email]
>> >
>> >> wrote:
>> >>
>> >> Hi,
>> >>
>> >> On 28/02/2017 9:02 PM, Wieland, Jacob wrote:
>> >>
>> >> Hi,
>> >>
>> >> I am observing a very strange behavior.
>> >>
>> >> In our generated code (due to various reasons I won't go into here
>> unless
>> >> I have to, but trust me, they are legit), we throw static exceptions
>> for
>> >> control flow purposes, This seems to work fine and without performance
>> loss
>> >> most of the time. However, we are observing now that every few
>> seconds, a
>> >> throw sometimes takes up between 1,5 and 2.5 seconds! (in contrast to
>> the
>> >> normal almost non-measurable time).
>> >>
>> >> Update: it seems that the observed behavior was kind of related with
>> some
>> >> extraneous circumstances (the computer seems to have been more lagged
>> than
>> >> usual at that point). By now, I can only observe throws that take up
>> to 20
>> >> milliseconds (which opposed to the normal time still seems slow).
>> >>
>> >> It does not seem to be GC related, the only idea that I have is the
>> jitter.
>> >>
>> >>
>> >> What jitter?
>> >>
>> >> I'm assuming Jacob is referring to the JIT.  But yes, he needs to
>> provide
>> >> more information.
>> >>
>> >> In particular, it would be good to know the following, as David
>> mentioned,
>> >> (off the top of my head):
>> >> 1) JVM cmdline flags
>> >>
>> >> -Xdebug -Xrunjdwp:transport=dt_socket,address=8001,server=y,suspend=y
>> >>
>> >> 2) Type of exception thrown (with a stacktrace or not)
>> >>
>> >> Exception class derived from java.lang.Error that overrides
>> >> fillInStackTrace() with 'return this', so stackless. Same instances
>> stored
>> >> in static final fields are always thrown.
>> >>
>> >> 3) Is the call stack depth about the same during the slow and fast
>> throws?
>> >>
>> >> It is always exactly the same stack, as it happens in a loop.
>> >>
>> >> 4) Is the exception thrown frequently or infrequently?
>> >>
>> >> In the test where this was observed, the exception was thrown every
>> 40ms,
>> >> so, I guess, frequently.
>> >>
>> >> 5) Is there -XX:+PrintCompilation output available around the time when
>> >> the slowdown is observed
>> >>
>> >> Unfortunately not, and at the moment, I cannot reproduce the behavior.
>> >>
>> >> I made a mockup-test (see attachment) that mimicks kind of what my
>> >> generated code does and adds measurements before throw and after catch.
>> >> Mostly, in my experiments with this, the throw takes on average 20 ns,
>> >> but between a 1 and 3 per million iterations take longer than 1 ms, on
>> >> average around 7 ms. It can be observed that doing a garbage
>> collection in
>> >> a different java process (namely my eclipse that started the test)
>> greatly
>> >> influences the frequency of the > 1 ms throws, so maybe it is simply a
>> load
>> >> issue. Using multiple threads in parallel also seems to heighten the
>> >>
>> >> Also, when introducing an additional sleep between iterations (like in
>> my
>> >> original scenario where I was waiting for a timer to timeout before
>> >> executing the construct that used the throw), I cannot reproduce such
>> >> outliers at all.
>> >>
>> >>
>> >>
>> >> So, my question is. Is this a known (and for some strange reason maybe
>> >> even accepted) behavior or is this a bug that I should file with
>> Oracle (or
>> >> you guys).
>> >>
>> >>
>> >> You really are not giving us anything to go on here. How are you
>> observing
>> >> this slowness? Exactly how do you throw? What exactly are you
>> measuring?
>> >> What's the execution context, the machine, processors etc etc etc.
>> >>
>> >>
>> >> I was observing the slowness in a testcase where I wanted regular
>> >> intervals of 40 ms between sending a message via UDP but frequently
>> (every
>> >> few seconds) got a lag of around 1.5 seconds (and a few days later 0.5
>> >> seconds) before the timer which timed out at the correct time was
>> noted.
>> >>
>> >>
>> >> When eliminating one kind of such thrown control exception, the next
>> kind
>> >> of thrown control exception (from a surrounding construct) was having
>> the
>> >> same effect which actually led me to the slow-throw-hypothesis.
>> Eliminating
>> >> all exceptions in the small example confirmed this hypothesis, but
>> going
>> >> that route would take a lot of effort for all cases and introduce other
>> >> additional imperformances (as I basically have to mock the exception
>> >> throwing via cascading return and if-checks on every level) which I
>> would
>> >> like to avoid.
>> >>
>> >> Regards,
>> >> David
>> >>
>> >>
>> >>
>> >>
>> >>
>> >> Spirent Communications e-mail confidentiality.
>> >> ------------------------------------------------------------
>> ------------
>> >> This e-mail contains confidential and / or privileged information
>> >> belonging to Spirent Communications plc, its affiliates and / or
>> >> subsidiaries. If you are not the intended recipient, you are hereby
>> >> notified that any disclosure, copying, distribution and / or the
>> taking of
>> >> any action based upon reliance on the contents of this transmission is
>> >> strictly forbidden. If you have received this message in error please
>> >> notify the sender by return e-mail and delete it from your system.
>> >>
>> >> Spirent Communications plc
>> >> Northwood Park, Gatwick Road, Crawley, West Sussex, RH10 9XN, United
>> >> Kingdom.
>> >> Tel No. +44 (0) 1293 767676 <+44%201293%20767676>
>> >> Fax No. +44 (0) 1293 767677 <+44%201293%20767677>
>> >>
>> >> Registered in England Number 470893
>> >> Registered at Northwood Park, Gatwick Road, Crawley, West Sussex, RH10
>> >> 9XN, United Kingdom.
>> >>
>> >> Or if within the US,
>> >>
>> >> Spirent Communications,
>> >> 27349 Agoura Road, Calabasas, CA, 91301, USA.
>> >> Tel No. 1-818-676- 2300 <(818)%20676-2300>
>> >>
>> >> --
>> >> Sent from my phone
>> >>
>>
>> --
>> Sent from my phone
>>
>>
>> --
> Sent from my phone
>