Fw: throwing static exceptions sometimes VERY slow!
Ioi Lam
ioi.lam at oracle.com
Thu Mar 2 06:12:14 UTC 2017
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 <vitalyd at gmail.com> 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 <Jacob.Wieland at spirent.com>
>> wrote:
>>
>>
>>
>>
>> sorry, forgot the attachment
>>
>>
>> BR
>>
>>
>>
>> *Dr. Jacob Wieland*
>>
>> *Senior Software Engineer*
>>
>> main +49.30.7261919.34
>>
>> mobile +49.173.6446443
>>
>>
>> jacob.wieland at spirent.com
>>
>>
>> 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:* hotspot-dev at openjdk.java.net
>>
>> *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
>>
>>
>> jacob.wieland at spirent.com
>>
>>
>> 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 <vitalyd at gmail.com>
>> *Sent:* Tuesday, February 28, 2017 1:46:09 PM
>> *To:* David Holmes
>> *Cc:* Wieland, Jacob; hotspot-dev at openjdk.java.net
>> *Subject:* Re: throwing static exceptions sometimes VERY slow!
>>
>>
>>
>> On Tue, Feb 28, 2017 at 7:37 AM, David Holmes <david.holmes at oracle.com>
>> 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
>>
More information about the hotspot-dev
mailing list