jHiccup and black magic spells

[Simone Bordet]

Hi,

quoting Gil:

"Finding the cause of hiccups/jitters in a a Linux system is black magic. You often look at the spikes and imagine "what could be causing this". "

We have a system where we don't have a super-small latency requirements, but we would like to stay within the 500 ms.
We run jHiccup and in a few cases we noticed 1000+ ms hiccups, up to 3000 ms.
Curiously enough, these spikes seem to happen during GC reference processing of the main JVM.

THP = off
vm.swappiness = 0
vm.min_free_kbytes = 135168
vm.zone_reclaim_mode = 1

We have run jHiccup within the main JVM without any special affinity to a core, or isolation.
We plan to run it in a separate JVM, but I would like to gather some experience from the people in this list about what would be the best way to run it.

Does jHiccup need to run on its own isolated core ?
If so, does it already pin its thread to a core, or it would require some code change to do it ?

What are the magic spells that people use that bring them from a jHiccup spike to the reason that caused it ?
What can possibly cause a 3000 ms hiccup ?

​Below the jHiccup report.​

Note that when the hiccups happen, they typically last few seconds.

​Thanks !

--
Simone Bordet
http://bordet.blogspot.com
---
Finally, no matter how good the architecture and design are,
to deliver bug-free software with optimal performance and reliability,
the implementation technique must be flawless.   Victoria Livschitz

[Vitaly Davidovich]

Yes, it's black magic particularly when jitter is rare and can't be predictably caught in the act.

What linux kernel version is this? What hardware, including disk? What filesystem? When you say this happens during GC reference processing, are you specifically referring to the Reference (e.g. weak, soft) processing phase or a GC cycle in general? If the latter, is this Full GC? Which GC are you using? How many GC worker threads are configured? How much disk writeback is occuring?

You can get fairly long systemwide stalls when the kernel is performing lots of dirty page writebacks to a slow disk and you happen to hit a codepath that's dirtying a file backed memory page.

sent from my phone

--
You received this message because you are subscribed to the Google Groups "mechanical-sympathy" group.
To unsubscribe from this group and stop receiving emails from it, send an email to mechanical-symp...@googlegroups.com.
For more options, visit https://groups.google.com/d/optout.

[Gil Tene]

Simon, assuming the jHiccup log you plot above from a jHiccup run within the application's JVM (e.g. by adding at as an agent to the command line for that application's JVM launch), then the output is most likely indicative of your GC behavior within that JVM. While it *may* be caused by things outside of that JVM (like Linux-related artifacts), that's not something you can tell without comparing your in-application jHiccup log with the output from another jHiccup running at the same time in another (idle) process.

Luckily, jHiccup has a "-c" flag option that launches just such an idle control process to compare logs with, since this is a very common need. If you launch jHiccup as an agent in your main application and give it the "-c" flag, you will end up with two separate log files. One for your application's process, and one for a co-start/co-terminating idle control process. Looking at both of these logs side by side will tell you a lot about where to look for the causes of externally observed latency spikes (in the JVM, in the system, or in your application code or network): 

- If both logs show spikes that happen at the same time, and are of a similar magnitude, your issue is not your code or the network, and it's not inside the JVM. It's your entire system that is glitching, and you'll want to look for the usual suspects: swapping, scheduling conflicts, paging, THP, power settings, blame the hypervisor, etc. That's where the black magic part usually comes in.

- If the in-application log shows a spike without a corresponding spike of a similar magnitude happening in the control log, the problem is not the system, and not the code or the network, it's the JVM. Your primary suspect then would be GC (and you'll likely find evidence to match in your GC logs), but it could be other things (like long time-to-safepoint (TTSP) coupled with lock debiasing, or with deoptimization, or one of the other 17 non-GC reasons a JVM might decide to pause).

- If you both logs are clean (and you have an externally observed spike), your culprit is most likely in the application code or network behavior (e.g. the application may have gone off to do some periodic internal book-keeping without responding, or you may have had a spike of incoming requests and you are simply seeing queueing latency, or some such).

It's this after-the-fact triage help that has attracted people to running jHiccup (with -c) in production (as opposed to just in lab tests).

In your specific case below, and simply based on eyeballing the chart without benefit of a control hiccup log, my guess is that your hiccup chart is dominated by GC pauses (both the regular ones in the 100s of msec range, and the occasional >1sec ones). A control log would make it clear if that's the case. And you probably already know what my recommendation for trivially getting rid of all such constant and occasional blipping will be... ;-).

Regarding your question about jHiccup and core affinity (should you run it on an isolated core, etc.): You would not normally want to isolate jHiccup. Quite the opposite. jHiccup is meant to observe the hiccup experiences of the process that launches it. As such it (intentionally) does not pin it's thread or do anything special with it to keep it away from other threads. jHiccup's hiccup-observing observing thread will run within whatever set of cores the JVM as a whole gets to run (which is normally the whole system, but may be affected by intentional use of numactl, taskset or cpusets), and by doing so it gets to report on the experience that other threads would see within that process. Similarly, the control process (if you use a -c flag) is launched from the application process, and will therefore tend to inherit the same set of cores to run on, reporting on the control (idle process) experience within the same set that the JVM runs on. Things only get messy when you start assigning core affinity to specific threads within your process (using something like Peter Lawrey's cool thread affinity library) and/or play with isolcpus. When you do that, the experience of the jHiccup thread no longer relates to the experience of the individually controlled or isolated threads. You can run core-isolated jHiccup experiments to see what isolated core behavior would look like in general, but it's hard to collect data about the actual experience on an isolated core of a dedicated thread, because Heisenberg.

-- Gil.

[Simone Bordet]

Gil,

thanks for your answers.

On Fri, Aug 7, 2015 at 5:48 PM, Gil Tene <g...@azulsystems.com> wrote:
>
> Simon, assuming the jHiccup log you plot above from a jHiccup run within the application's JVM (e.g. by adding at as an agent to the command line for that application's JVM launch), then the output is most likely indicative of your GC behavior within that JVM. While it *may* be caused by things outside of that JVM (like Linux-related artifacts), that's not something you can tell without comparing your in-application jHiccup log with the output from another jHiccup running at the same time in another (idle) process.

Right.

> Luckily, jHiccup has a "-c" flag option that launches just such an idle control process to compare logs with, since this is a very common need. If you launch jHiccup as an agent in your main application and give it the "-c" flag, you will end up with two separate log files. One for your application's process, and one for a co-start/co-terminating idle control process. Looking at both of these logs side by side will tell you a lot about where to look for the causes of externally observed latency spikes (in the JVM, in the system, or in your application code or network):
>

> - If both logs show spikes that happen at the same time, and are of a similar magnitude, your issue is not your code or the network, and it's not inside the JVM. It's your entire system that is glitching, and you'll want to look for the usual suspects: swapping, scheduling conflicts, paging, power settings, blame the hypervisor, etc. That's where the black magic part usually comes in.

I was thinking that if, for whatever reason, the main JVM burns all
the cores and has a large number of threads, the control JVM may not
have the chance to run, and therefore report a spike that is directly
caused by the main JVM, with similar magnitude. If that is true, then
I would look at the OS where it's actually the main JVM. That's why I
asked about isolation and pinning of the control JVM. Am I off path
here ?

> - If the in-application log shows a spike without a corresponding spike of a similar magnitude happening in the control log, the problem is not the system, and not the code or the network, it's the JVM. Your primary suspect then would be GC (and you'll likely find evidence to match in your GC logs), but it could be other things (like long time-to-safepoint (TTSP) coupled with lock debiasing, or with deoptimization, or one of the other 17 non-GC reasons a JVM might decide to pause).
>
> - If you both logs are clean (and you have an externally observed spike), your culprit is most likely in the application code or network behavior (e.g. the application may have gone off to do some periodic internal book-keeping without responding, or you may have had a spike of incoming requests and you are simply seeing queueing latency, or some such).
>
> It's this after-the-fact triage help that has attracted people to running jHiccup (with -c) in production (as opposed to just in lab tests).
>
> In your specific case below, and simply based on eyeballing the chart without benefit of a control hiccup log, my guess is that your hiccup chart is dominated by GC pauses (both the regular ones in the 100s of msec range, and the occasional >1sec ones). A control log would make it clear if that's the case. And you probably already know what my recommendation for trivially getting rid of all such constant and occasional blipping will be... ;-).
>

:D

Of course, and it actually happens that my client has followed your
recommendations too ;)

It's going to take some time though (on my client's part), and if it's
a G1 bug, we would be happy to identify it and contribute to Hotspot
at least the details about the case.
Right now we have these multi second pauses most of the times while
processing 0 SoftReferences, e.g.:

2015-08-05T20:25:47.142-0700: 68719.714: [GC pause (G1 Evacuation Pause) (young)
68719.800: [SoftReference, 0 refs, 1.2469771
secs]68721.047:[WeakReference, 1 refs, 0.0055752 secs]68721.053:
[FinalReference, 4056 refs, 0.0068966 secs]68721.059:
[PhantomReference, 2 refs, 1 refs, 0.0101259 secs]68721.070: [JNI Weak
Reference, 0.0000337 secs],1.3682536 secs]
[Times: user=1.93 sys=0.01, real=1.37 secs]

I have a thread open in the hotspot-gc mailing list about this, we're
trying to gather more information about what can be causing this.

> Regarding your question about jHiccup and core affinity (should you tun it on an isolated core, etc.): You would not normally want to isolate jHiccup. Quite the opposite. jHiccup is meant to observe the hiccup experiences of the process that launches it. As such it (intentionally) does not pin it's thread or do anything special with it to keep it away from other threads. jHiccup's hiccup-observing observing thread will run within whatever set of cores the JVM as a whole gets to run (which is normally the whole system, but may be affected by intentional use of numactl, taskset or cpusets), and by doing so it gets to report on the experience that other threads would see within that process. Similarly, the control process (if you use a -c flag) is launched from the application process, and will therefore tend to inherit the same set of cores to run on, reporting on the control (idle process) experience within the same set that the JVM runs on. Things only get messy when you start assigning core affinity to specific threads within your process (using something like Peter Lawrey's cool thread affinity library) and/or play with isolcpus. When you do that, the experience of the jHiccup thread no longer relates to the experience of the individually controlled or isolated threads. You can run core-isolated jHiccup experiments to see what isolated core behavior would look like in general, but it's hard to collect data about the actual experience on an isolated core of a dedicated thread, because Heisenberg.
>

Mmm. See above, I am not yet convinced that if both logs, running with
-c, show the same peaks, then it's not an effect of the main JVM. And
if it is I would need darker black magic because I would have first to
look at figuring out whether it's the JVM or the OS, and then apply
the usual black magic.

Thanks !

[Simone Bordet]

Hi,

thanks for your answers !

On Fri, Aug 7, 2015 at 5:19 PM, Vitaly Davidovich <vit...@gmail.com> wrote:
>
> Yes, it's black magic particularly when jitter is rare and can't be predictably caught in the act.
>
> What linux kernel version is this? What hardware, including disk? What filesystem? When you say this happens during GC reference processing, are you specifically referring to the Reference (e.g. weak, soft) processing phase or a GC cycle in general? If the latter, is this Full GC? Which GC are you using? How many GC worker threads are configured? How much disk writeback is occuring?
>
> You can get fairly long systemwide stalls when the kernel is performing lots of dirty page writebacks to a slow disk and you happen to hit a codepath that's dirtying a file backed memory page.

It's a CentOS:
Linux 2.6.32-358.14.1.el6.x86_64 #1 SMP Tue Jul 16 23:51:20 UTC 2013
x86_64 x86_64 x86_64 GNU/Linux

EXT4 FileSystem.

CPU:
Intel(R) Xeon(R) CPU E5-4640 0 @ 2.40GHz (4 sockets, 8 cores / socket
hyper-threaded => 64 "threads")

RAM: 64 GiB.

Using G1, and yes I am referring to SoftReference processing, see the
answer to Gil for a snippet log that shows the problem.

The system is certainly writing *a lot* of application logs to disk,
but I'm not sure how to get the writeback information you asked, can
you help ?

[Gil Tene]

On Friday, August 7, 2015 at 9:27:48 AM UTC-7, Simone Bordet wrote:

Gil,

thanks for your answers.

On Fri, Aug 7, 2015 at 5:48 PM, Gil Tene <g...@azulsystems.com> wrote:
>
> Simon, assuming the jHiccup log you plot above from a jHiccup run within the application's JVM (e.g. by adding at as an agent to the command line for that application's JVM launch), then the output is most likely indicative of your GC behavior within that JVM. While it *may* be caused by things outside of that JVM (like Linux-related artifacts), that's not something you can tell without comparing your in-application jHiccup log with the output from another jHiccup running at the same time in another (idle) process.

Right.

> Luckily, jHiccup has a "-c" flag option that launches just such an idle control process to compare logs with, since this is a very common need. If you launch jHiccup as an agent in your main application and give it the "-c" flag, you will end up with two separate log files. One for your application's process, and one for a co-start/co-terminating idle control process. Looking at both of these logs side by side will tell you a lot about where to look for the causes of externally observed latency spikes (in the JVM, in the system, or in your application code or network):
>
> - If both logs show spikes that happen at the same time, and are of a similar magnitude, your issue is not your code or the network, and it's not inside the JVM. It's your entire system that is glitching, and you'll want to look for the usual suspects: swapping, scheduling conflicts, paging, power settings, blame the hypervisor, etc. That's where the black magic part usually comes in.

I was thinking that if, for whatever reason, the main JVM burns all
the cores and has a large number of threads, the control JVM may not
have the chance to run, and therefore report a spike that is directly
caused by the main JVM, with similar magnitude. If that is true, then
I would look at the OS where it's actually the main JVM. That's why I
asked about isolation and pinning of the control JVM. Am I off path
here ?

The control log may show a spike when the JVM is blasting away with many GC threads, but it's not going to be anywhere close in magnitude (hence the "happen at the same time, and are of a similar magnitude" comment above). For a control process to see a hiccup larger than 10-20msec due to cpu scheduling contention, you'd need a lot more CPU scheduling pressure than a GC will generate from a neighboring process. E.g. the nearly-idle HiccupMeter thread would need to compete with ~50+ runnable threads on the same core to experience a 500msec blip (which would mean that there are many 100s of ready to run threads on the systems - and that's not something a GC does). I've certainly seen control hiccup logs with 1/2 second blips in them, but when you do see blips of such magnitude in control logs, they are usually not due to CPU pressure but something else (like swapping/paging/THP/power-management).

[Simone Bordet]

Hi,

On Fri, Aug 7, 2015 at 6:46 PM, Gil Tene <g...@azulsystems.com> wrote:
> The control log may show a spike when the JVM is blasting away with many GC
> threads, but it's not going to be anywhere close in magnitude (hence the
> "happen at the same time, and are of a similar magnitude" comment above).
> For a control process to see a hiccup larger than 10-20msec due to cpu
> scheduling contention, you'd need a lot more CPU scheduling pressure than a
> GC will generate from a neighboring process. E.g. the nearly-idle
> HiccupMeter thread would need to compete with ~50+ runnable threads on the
> same core to experience a 500msec blip (which would mean that there are many
> 100s of ready to run threads on the systems - and that's not something a GC
> does). I've certainly seen control hiccup logs with 1/2 second blips in
> them, but when you do see blips of such magnitude in control logs, they are
> usually not due to CPU pressure but something else (like
> swapping/paging/THP/power-management).

Thanks for this explanation!

[Vitaly Davidovich]

That's a fairly old kernel :)

The system is certainly writing *a lot* of application logs to disk,
but I'm not sure how to get the writeback information you asked, can
you help ?

/proc/meminfo will have Dirty and Writeback stats that you can watch as the benchmark/application is running.  You may also be able to look at /proc/<pid>/sched and check if you're seeing iowait counters going up.

 

I actually recall seeing your email to hotspot-gc now about this -- the running theory is that there's some other task that's being attributed to ref processing even though it's not, right?