These are chat archives for ManageIQ/manageiq/performance

12th
Dec 2017
Keenan Brock
@kbrock
Dec 12 2017 14:55
native gems latest 5.9 5.8
bcrypt 3.1.11 3.1.10 3.1.11
ffi 1.9.18 1.9.8 1.9.18
hamlit 2.7.5 2.7.2 2.7.5
http_parser.rb 0.6.0 0.6.0 0.6.0 same
linux_block_device 0.2.1 0.2.1 0.2.1 same
nio4r 2.1.0 0.2.1 2.1.0
nokogiri 1.8.1 1.8.1 1.8.1 same
memory_buffer 0.1.0 0.1.0 0.1.0 same
ovirt-engine-sdk 4.2.0 4.1.5 4.1.13
pg 0.18.4 0.18.2 0.18.4
puma 3.7.1 3.3.0 3.7.1
rugged 0.25.1.1 0.25.0 0.25.1.1
unf_ext 0.0.7.4 0.0.7.1 0.0.7.4
websocket-driver 0.6.5 0.6.3 0.6.5
@NickLaMuro
Brandon Dunne
@bdunne
Dec 12 2017 15:06
looks like a lot of gems that were downgraded in 5.9
Joe Rafaniello
@jrafanie
Dec 12 2017 15:15
@dmetzger57 @NickLaMuro have you deployed the latest upstream master with the idle test to see if it leaks?
Dennis Metzger
@dmetzger57
Dec 12 2017 15:19
@jrafanie saw it on the 12/06/2017 build, latest Master I tried
Joe Rafaniello
@jrafanie
Dec 12 2017 15:19
cool, @dmetzger57 can you PM me the ip? I'd like to take a look
Dennis Metzger
@dmetzger57
Dec 12 2017 15:20
I’ll see if I still have that image, may have “recycled” it
Joe Rafaniello
@jrafanie
Dec 12 2017 15:22
ok, feel free to send me other ones... I want to see if there's something I didn't notice before :-(
Keenan Brock
@kbrock
Dec 12 2017 16:34
@bdunne good eye - I swapped the 2 headers
@agrare was suggesting that we may want to ensure that pg did not introduce a problem
Keenan Brock
@kbrock
Dec 12 2017 16:40
that looks like it was closed with nothing much there - I'm still curious about that version of pg
Nick LaMuro
@NickLaMuro
Dec 12 2017 16:42
looks like it was related to ruby's GC, which would suggest it is not a c-ext based issue, which we are pretty confident at this point is our issue.
Keenan Brock
@kbrock
Dec 12 2017 16:44
@NickLaMuro are you looking into the scheduler?
The things that wait 5 minutes to start?
I can look into this if you want
Nick LaMuro
@NickLaMuro
Dec 12 2017 16:47
I haven't looked into it, no
that said, I wouldn't be afraid to double up on something at this point
the more eyes on this the better
Keenan Brock
@kbrock
Dec 12 2017 16:47
I'll quickly check the ones with 5 minute delays
@NickLaMuro 5 minutes is my target. right?
Nick LaMuro
@NickLaMuro
Dec 12 2017 16:49
target for what?
are you talking about five minutes it leaks memory?
Keenan Brock
@kbrock
Dec 12 2017 16:50
hmm. when does the memory start taking off?
I misread the flat part of the graph
Nick LaMuro
@NickLaMuro
Dec 12 2017 16:51
can't speak for @dmetzger57 's graph, but mine tend to have a spike, then a linear growth: https://gitter.im/ManageIQ/manageiq/performance?at=5a2eb4aa0163b0281022fdb4
which I can attribute the spike to autoloading most likely
Joe Rafaniello
@jrafanie
Dec 12 2017 17:07

I mentioned this to @dmetzger57 but wanted to say it here.. I don't know if it's related but I wonder if the way in which memory moves to AnonHugePages could be in play here.

I'm seeing 0 AnonHugePages on a fresh miq server process running less than a few hours:

01ac0000-18395000 rw-p 00000000 00:00 0                                  [heap]
Size:             369492 kB
Rss:              308844 kB
Pss:              210261 kB
Shared_Clean:          0 kB
Shared_Dirty:     109076 kB
Private_Clean:         0 kB
Private_Dirty:    199768 kB
Referenced:       308844 kB
Anonymous:        308844 kB
AnonHugePages:         0 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Locked:                0 kB
VmFlags: rd wr mr mw me ac sd
on the example appliances from Dennis, the 5.8 appliance has:
02385000-243f8000 rw-p 00000000 00:00 0                                  [heap]
Size:             557516 kB
Rss:              542444 kB
Pss:              449265 kB
Shared_Clean:          0 kB
Shared_Dirty:     103192 kB
Private_Clean:         0 kB
Private_Dirty:    439252 kB
Referenced:       542444 kB
Anonymous:        542444 kB
AnonHugePages:    200704 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Locked:                0 kB
VmFlags: rd wr mr mw me ac sd
on the 5.9 appliance:
00c0c000-4176b000 rw-p 00000000 00:00 0                                  [heap]
Size:            1060220 kB
Rss:             1043996 kB
Pss:              964126 kB
Shared_Clean:          0 kB
Shared_Dirty:      88500 kB
Private_Clean:         0 kB
Private_Dirty:    955496 kB
Referenced:      1043996 kB
Anonymous:       1043996 kB
AnonHugePages:    729088 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Locked:                0 kB
VmFlags: rd wr mr mw me ac sd
and the master appliance:
01d64000-1db64000 rw-p 00000000 00:00 0                                  [heap]
Size:             456704 kB
Rss:              440896 kB
Pss:              366505 kB
Shared_Clean:          0 kB
Shared_Dirty:      82376 kB
Private_Clean:         0 kB
Private_Dirty:    358520 kB
Referenced:       440896 kB
Anonymous:        440896 kB
AnonHugePages:    155648 kB
Swap:                  0 kB
KernelPageSize:        4 kB
MMUPageSize:           4 kB
Locked:                0 kB
VmFlags: rd wr mr mw me ac sd
Nick LaMuro
@NickLaMuro
Dec 12 2017 17:11
interesting, hmm
Joe Rafaniello
@jrafanie
Dec 12 2017 17:11
nodejs/node#11077
the nodejs issue is an interesting read
:neckbeard:
Oh well, lunch time!
It might be worth seeing what happens if we disable transparent huge pages or configure some knobs there
Nick LaMuro
@NickLaMuro
Dec 12 2017 17:54
So, we can rule out heartbeat as being the cause I think:
20171211_15033.png
Nick LaMuro
@NickLaMuro
Dec 12 2017 17:59
damn... looks like #process_miq_queue is also not the issue...
20171211_12355.png
so both machines end up with workers that look like this:
Screen Shot 2017-12-12 at 12.01.11 PM.png
instead of this:
Screen Shot 2017-12-12 at 12.01.42 PM.png
so, my thought it it either is the DRB communication from the workers asking for messages, or something in the #monitor_workers code (which is somewhat involved under the hood) that is causing the leak).
For reference, this is basically what the MiqServer#monitor method looks like at the moment:
def monitor
  now = Time.now.utc
  Benchmark.realtime_block(:heartbeat)               { heartbeat }                        if threshold_exceeded?(:heartbeat_frequency, now)
  Benchmark.realtime_block(:server_dequeue)          { process_miq_queue }                if threshold_exceeded?(:server_dequeue_frequency, now)

  # Benchmark.realtime_block(:server_monitor) do
  #   monitor_servers
  #   monitor_server_roles if self.is_master?
  # end if threshold_exceeded?(:server_monitor_frequency, now)

  # Benchmark.realtime_block(:log_active_servers)      { log_active_servers }               if threshold_exceeded?(:server_log_frequency, now)
  # Benchmark.realtime_block(:worker_monitor)          { monitor_workers }                  if threshold_exceeded?(:worker_monitor_frequency, now)
  # Benchmark.realtime_block(:worker_dequeue)          { populate_queue_messages }          if threshold_exceeded?(:worker_dequeue_frequency, now)
rescue SystemExit, SignalException
  #...
end
Nick LaMuro
@NickLaMuro
Dec 12 2017 18:04
The first appliance, then having the #process_miq_queue code commented out as well
also, one of those (I forget which without looking) is still doing the extended logging, so that doesn't seem to have any affect on what we are capturing here
(also, graphs are generated from the top_output.log files)
Nick LaMuro
@NickLaMuro
Dec 12 2017 18:10

I think the above graphs have provided enough info to go off of and running any longer is probably not necessary, so I think I am going to try parallel experiments to narrow things down further:

  • Both boxes will uncomment #monitor_workers from above
  • 1 will remove all roles necessary so that it only enable a single MiqGenericWorker, MiqPriorityWorker, and MiqPriorityWorker

That way, we can determine if the leak is from the workers interacting on the DRB thread, or if it is something else

my gut tells me that the results will be the same on both boxes since the MiqGenericWorker is a queue worker as well, and should be opening it's own DRB thread, but we will see
Dennis Metzger
@dmetzger57
Dec 12 2017 18:11
Agreed, time to start adding back code paths
Keenan Brock
@kbrock
Dec 12 2017 18:49
@NickLaMuro if you drop the monitor message onto the floor, dies it still cause the issue? (is it Settings related?
Joe Rafaniello
@jrafanie
Dec 12 2017 18:53
@NickLaMuro sorry, were these idle appliances?
Nick LaMuro
@NickLaMuro
Dec 12 2017 18:58
these have cap&u enabled, but as mentioned probably at some point previously, those workers are not doing anything
Keenan Brock
@kbrock
Dec 12 2017 18:59
so the only real work is reloading the settings?
Nick LaMuro
@NickLaMuro
Dec 12 2017 18:59

@NickLaMuro if you drop the monitor message onto the floor

@kbrock Huh? What is this?

Keenan Brock
@kbrock
Dec 12 2017 18:59
@NickLaMuro sorry - thinking the client side not the server side
Jason Frey
@Fryguy
Dec 12 2017 19:00
@NickLaMuro It could also be a pair of methods that in isolation don't leak but together do
Nick LaMuro
@NickLaMuro
Dec 12 2017 19:01

so, my thought it it either is the DRB communication from the workers asking for messages, or something in the #monitor_workers code (which is somewhat involved under the hood) that is causing the leak).

@Fryguy yeah, sorry, this was never meant to imply these are the only two possibly issues

Nick LaMuro
@NickLaMuro
Dec 12 2017 19:08
that said, the above is kinda hard to reproduce
Joe Rafaniello
@jrafanie
Dec 12 2017 19:12
Joe Rafaniello
@jrafanie
Dec 12 2017 19:32

from the first link...

"THP(transparent huge pages) attempts to create 2MB mappings. However, it’s overly greedy in doing so, and too unwilling to break them back up if necessary. If an application maps a large range but only touches the first few bytes, it would traditionally consume only a single 4KB page of physical memory. With THP enabled, khugepaged can come and extend that 4KB page into a 2MB page, effectively bloating memory usage by 512x (An example reproducer on this bug report actually demonstrates the 512x worst case!).

This behavior isn’t hypothetical; Go’s GC had to include an explicit workaround for it, and Digital Ocean documented their woes with Redis, THP, and the jemalloc allocator."

:pray: for silver bullet
Joe Rafaniello
@jrafanie
Dec 12 2017 19:54
@dmetzger57 I did it on my local appliance and I'll let it run for a bit. tl;dr https://access.redhat.com/solutions/1320153, but instead I added transparent_hugepage=madvise to my GRUB_CMDLINE_LINUX in /etc/default/grub and ran grub2-mkconfig -o /boot/grub2/grub.cfg, rebooted and confirmed cat /proc/cmdline showed transparent_hugepage=madvise. We should probably try transparent_hugepage=never too but I wanted to try it so applications that are optimized for transparent hugepages can use them
Jason Frey
@Fryguy
Dec 12 2017 19:59
ugh
just like MALLOC_ARENA, it feels like in trying to solve problem a they just create problems b and c
Nick LaMuro
@NickLaMuro
Dec 12 2017 20:01
@jrafanie were you able to start recreating the leak on an appliance?
Joe Rafaniello
@jrafanie
Dec 12 2017 20:03
@NickLaMuro not reliably since I'm running locally
@Fryguy it's not confirmed yet but yes, it feels like a feature for massive memory application servers and we don't fit that mold
Joe Rafaniello
@jrafanie
Dec 12 2017 20:19
@dmetzger57 @NickLaMuro can you try disabling or using madvise for transparent_hugepage?
also, can you try deploying an appliance completely unchanged but give it only 4 GB of memory? I wonder if you have a significant amount of memory on the system, it might freely give out hugepages
Nick LaMuro
@NickLaMuro
Dec 12 2017 20:25
@jrafanie since I just started a test on the two VM's I am using, no
Joe Rafaniello
@jrafanie
Dec 12 2017 20:25
ok
Nick LaMuro
@NickLaMuro
Dec 12 2017 20:25
I can maybe try it tomorrow
but I would want conclusive data first
Joe Rafaniello
@jrafanie
Dec 12 2017 20:25
sure
Nick LaMuro
@NickLaMuro
Dec 12 2017 20:26
@dmetzger57 might be able to help, but I think he has another meeting after just getting out of one with me
Joe Rafaniello
@jrafanie
Dec 12 2017 20:26
it's hard to be conclusive when it takes an entire work day to be sure it's happening
Nick LaMuro
@NickLaMuro
Dec 12 2017 20:27
when it is a flat line, I am pretty confident after a day, but with a slope that leads to a "leak", I like letting it go for more usually
Dennis Metzger
@dmetzger57
Dec 12 2017 20:27
@jrafanie I’ll experiment with transparent_hugepage and try a limited memory appliance
Joe Rafaniello
@jrafanie
Dec 12 2017 20:30
@dmetzger57 make sure you use the grub2-mkconfig command. One of the techniques mentioned in the one blog post above didn't work. The technote I summarized :point_up: December 12, 2017 2:54 PM worked for me
Dennis Metzger
@dmetzger57
Dec 12 2017 20:30
thanks for the heads up
Joe Rafaniello
@jrafanie
Dec 12 2017 20:32
FYI, it appears transparent huge pages were enabled by default in rhel/centos 6. I can't tell if anything about them changed from rhel/centos 6 to 7
Joe Rafaniello
@jrafanie
Dec 12 2017 20:38
I went back to default transparent_hugepage, increased my appliance memory, and rebooted, to @NickLaMuro's point, I want to be able to recreate what you're seeing before I fiddle knobs