Forum Stats

  • 3,825,283 Users
  • 2,260,497 Discussions
  • 7,896,478 Comments

Discussions

45 Second Periodic Performance Disruption

Bryce Guinta
Bryce Guinta Member Posts: 22
edited Mar 29, 2017 9:59AM in Vdbench

Hi Henk,

I came across a problem with vdbench performance reporting every 45 seconds and found a very similar thread:

Has there been any resolution in the works to this problem or perhaps a workaround? If not I would be willing to help you debug & reproduce the problem.

Some observations:

- This irregularity is more prominent at higher queue depths

I'm running Centos 7.3 with kernel 4.9.1.

No core goes over 5% cpu usage.

The below graph is from a 4K Read, 32QD workload which gives me about 76K IOPs. This particular workload is run on a loopback device, but I have reproduced it on solid-state drives.

Here's my summary.html

As you can see, like clockwork there is a problem with the reported actual queue depth (and subsequently the IOPs) for a 1 second interval. This reported actual queue depth goes over (threads+1) followed by an interval that reports an actual queue depth of less than (threads-1) every 45 seconds.

download.png

Best Answer

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 28, 2017 9:58AM Answer ✓

    Bryce,

    here is the fix, currently only accessible by you, as soon as I get an OK from you I'll open it to the world. The fix is only needed for Linux.

    This exact code has been around for 16 years, Chas probably still remembers when it started.

    It is understandable that it was not noticed: a 40 millisecond fluctuation in iops equals 1/25th of total iops and does not get noticed when doing only a few iops. In your case, 1/25th of 75,000 iops equals 3000 iops, and that does make a difference.

    Thank you so much for bringing this to my attention and providing me with all the data needed to get this fixed.

    Henk.

«1

Answers

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 25, 2017 10:48PM

    Every EXACTLY one second Vdbench sends a message to the slaves asking for performance statistics.

    Vdbench expects the data being returned to cover (almost) exactly one second.

    If however it takes a while for that request to arrive on the slaves (or be honored), the slave will be returning data covering a period of maybe a few milliseconds longer.

    Vdbench still assumes that the data covers exactly one second, so its calculations will be off, with a higher iops.

    The next interval, at again exactly one second, Vdbench sends the NEXT request. Because the slave the previous time was late responding, the data that he returns now covers maybe a few milliseconds shorter. Again, Vdbench assuming the data covers exactly one second now shows a lower iops.

    When systems are overloaded this can happen at random intervals, especially when remote systems are involved.

    Even on the best of systems you can see a slight variation every now and then.

    However as you observed, for you it happens every 'heartbeat/4' seconds.

    The only way I can explain this is that normal 'steady state' processing on the slave is interrupted by all of a sudden a different OS thread (heartbeat) waking up and needing a few cpu cycles to just return the heartbeat message back to the master. But why would this happen (in these two cases that I now have seen) EXACTLY at the same time that the Master asks for cpu statistics?

    That is the big unknown. Sending statistics requests as mentioned is synchronized on the exact one second, but the timing for the heartbeat messages sent is independent of that timing.

    Yes, in theory every now and then they can happen at the same time, but not for each test that you have run.

    Maybe there is something that somehow forces these messages to be synchronized on YOUR system. Let's find out.

    Please add -d48 as an execution parameter and run for five minutes and return logfile.html and localhost-0.stdout.html

    '-d48' will display all the message traffic, including timestamps.

    I don't expect an explanation, but the best we can do is try.

    Henk.

  • Bryce Guinta
    Bryce Guinta Member Posts: 22
    edited Mar 26, 2017 6:47PM

    I re-ran the parmfile as requested with the -d48 cli argument:

    I accidently left the -verbose:gc flag on from earlier debug exploration. The flag is responsible for the "Allocation Failure" messages from the JVM, which apparently don't mean anything.

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 26, 2017 6:55PM

    Thank you for explaining about the GC messages.

    And indeed, the REQUEST_SLAVE_STATISTICS is sent at the proper time from the master, but arrives about 40 milliseconds later at the slave causing the reporting anomaly.

    But why.

    Two requests:

    - Add -m2 as an execution parameter, that will run the work with two instead of the default one slave. Let's see how that works.

    And separately:

    - Every time someone reports strange problems and I see 'openjdk' I tell my users to download and install a proper java version from the Oracle website. Please do and rerun.

    I have seen too many weird problems with 'openjdk'.

    Henk.

  • Bryce Guinta
    Bryce Guinta Member Posts: 22
    edited Mar 26, 2017 8:07PM

    I made those changes, and it looks like not much has changed unfortunately:

    logfile.html

    localhost-0.stdout.html

    localhost-1.stdout.html

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 26, 2017 9:20PM

    It appears that the second slave is not used.

    Can you send me parmfile.html?

    It appears you are running pure sequential, single SD.

    Henk.

  • Chas Gimarc
    Chas Gimarc Member Posts: 1
    edited Mar 27, 2017 1:41PM

    Henk, we see this issue with either Sequential (one SD) or Random I/O streams.  Sequential should make it easier to understand.

    Also we have cases with an exactly 45 sec "ping" or irregularity, and others with 30 sec period.  Other than the period, the signature is the same.

    This is seen across multiple servers (all running CentOS 6.x or 7.x) using Vdbench 5.03.x or newer, and a variety of JRE's.

    As you mentioned in the thread, the positive excursion exactly matches the adjacent negative IOPs excursion, so on average it's not a problem.

    Except when one is paying attention to the STDEV of the "rate" or "MB/sec" metrics.

    Thanks.

  • Bryce Guinta
    Bryce Guinta Member Posts: 22
    edited Mar 27, 2017 2:31PM

    I was using a sequential workload, by bad. I modified the parmfile to run a random workload but not much has changed:

    https://gist.github.com/brycepg/bac8f04a26cb3a8ba982a234ab3ff88f

    It looks like the 40ms delay for the statistics reponse is only present in logfile.html output but the stdout files display a 1 ms delay. In logfile.html the 40ms delay is present for all of the requests, not just in the intervals where the IOPs/actual qd are misreported.

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 27, 2017 3:05PM

    The 40ms delay is there also always for 'USER_DATA_TO_SLAVES', though that message in itself is irrelevant.

    I am at a loss.

    - do you see this with different operating systems? Is it only CentOS?

    - 'loopback device', is that something special that can introduce this problem?

    It appears to me that something strange is happening in the handling of java socket traffic between the master and the slaves, but what, that is not clear.

    If we can't clear this up then I see the only way to work around this and still see this every 225 is to use the debug=27 or -d27 option as mentioned in the original posting of this problem.

    Henk.

  • Henk Vandenbergh-Oracle
    Henk Vandenbergh-Oracle Member Posts: 813
    edited Mar 27, 2017 3:35PM

    Just a thought: run this with elapsed=120,iorate=curve

    That will show if this problem is load related or not. (yes, I am grasping).

    Henk.

  • Bryce Guinta
    Bryce Guinta Member Posts: 22
    edited Mar 27, 2017 5:32PM

    Henk,

    1. This issue has been reproduced on many versions of CentOS. I was unable to reproduce the issue on Windows Server 2012 with the same parmfile(R4K100R 32QD workload). I could look into trying another Linux distro and trying a "minimal" install.
    2. Our data which spans years and tests different solid-state drives show this issue. The loopback device is a convenience factor for me, and shows that the problem does not lie with the solid state drive.

    Here's the curve data. I'm seeing the issue in most of the workloads, however some of them are too noisy:

    https://gist.github.com/ea88730a16bf1ebd948c46fcff17a110

    vdbench-rd.png

    vdbench-rd_(10%).pngvdbench-rd_(50%).pngvdbench-rd_(70%).pngvdbench-rd_(80%).pngvdbench-rd_(90%).pngvdbench-rd_(100%).png

This discussion has been closed.