These are chat archives for ManageIQ/manageiq/performance

24th
Oct 2015
Jason Frey
@Fryguy
Oct 24 2015 00:35
How in the hell do you get grep to do a regex alternation
I tired of trying to figure this out
Matthew Draper
@matthewd
Oct 24 2015 00:35
\|
Jason Frey
@Fryguy
Oct 24 2015 00:35
not working :(
I wants something like: ruby MiqVimBrokerServer.rb | grep "XXX\|started"
Matthew Draper
@matthewd
Oct 24 2015 00:36
(in single quotes, because shell)
Jason Frey
@Fryguy
Oct 24 2015 00:36
OMFG I HATE SHELL
thank you @matthewd
Matthew Draper
@matthewd
Oct 24 2015 00:36
:shell: :grin:
Jason Frey
@Fryguy
Oct 24 2015 00:37
Nope, that's not working either
:angry:
ruby MiqVimBrokerServer.rb | grep 'XXX\|started'
Matthew Draper
@matthewd
Oct 24 2015 00:38
% echo XXX | grep "XXX\|started"             
XXX
Are you sure there are matching lines? :P
Jason Frey
@Fryguy
Oct 24 2015 00:39
positive
The very first line it spits out is "Broker server started at druby://127.0.0.1:55900 with PID 84364"
Matthew Draper
@matthewd
Oct 24 2015 00:39
And you're getting no output at all?
Jason Frey
@Fryguy
Oct 24 2015 00:40
wtf, I can't even grep the word started by itself
wonder if it's a buffer sync thing
flush thingy ;)
:toilet:
Matthew Draper
@matthewd
Oct 24 2015 00:40
Ah, yes, that sounds plausible
Jason Frey
@Fryguy
Oct 24 2015 00:41
STDOUT.sync = true worked :(
I hate spending forever on problems that shouldn't matter
Matthew Draper
@matthewd
Oct 24 2015 00:41
heisenbuffer ftw
Jason Frey
@Fryguy
Oct 24 2015 00:42
:grin:
Jason Frey
@Fryguy
Oct 24 2015 02:27
I found a win!
Matthew Draper
@matthewd
Oct 24 2015 02:27
:eyes:
Keenan Brock
@kbrock
Oct 24 2015 02:27
yay win FTW
Jason Frey
@Fryguy
Oct 24 2015 02:27
Seems we are doing this RIDICULOUS debug logging
basically, before my patch after the handsoap response memory was 564_097_024
after my patch it's 444_801_024
120 MB or so win
Matthew Draper
@matthewd
Oct 24 2015 02:28
what even (-‸ლ)
Jason Frey
@Fryguy
Oct 24 2015 02:28
ikr?
let's just say there's this useless debug logging that PRETTY PRINTS THE DAMN XML WITH NOKOGIRI
so much rage
Matthew Draper
@matthewd
Oct 24 2015 02:29
Errrrrrr… where's that?
I'm surprised my SAX hackery didn't skip it :confused:
Jason Frey
@Fryguy
Oct 24 2015 02:30
because all this happens before that
getting link
Keenan Brock
@kbrock
Oct 24 2015 02:30
our logs are very verbose. sometimes feel they could use a little love.
Jason Frey
@Fryguy
Oct 24 2015 02:30
it's not even in our logs
Keenan Brock
@kbrock
Oct 24 2015 02:31
heh
Matthew Draper
@matthewd
Oct 24 2015 02:31
        debug do
          fire_on_log_header "HandSoap Response [#{dispatch_id}]: length: [#{response.content.length}], HTTP-Status: [#{response.status}], Content-Type: [#{response.contenttype}]"
          fire_on_log_body Handsoap.pretty_format_envelope(response.content)
        end
Is it that thing? :scream:
Jason Frey
@Fryguy
Oct 24 2015 02:32
yup
Matthew Draper
@matthewd
Oct 24 2015 02:32
gahhhh
Jason Frey
@Fryguy
Oct 24 2015 02:32
that second line
I got the patch locally...making PRs now
Matthew Draper
@matthewd
Oct 24 2015 02:32
I saw that, then ignored it, on the assumption that debug wouldn't be yielding
So, may be interesting to re-consider my SAX thing with that fixed
so because we set that callback, debug is considered true in handsoap
yeah...let me get you the patches, so you can play around...
there are a lot of wins in these handsoap patches
Matthew Draper
@matthewd
Oct 24 2015 02:34
So it's basically move that } back two words? :P
Jason Frey
@Fryguy
Oct 24 2015 02:34
yeah
and it requires a couple patches to handsoap too
er...our handsoap fork to be fair to handsoap
Matthew Draper
@matthewd
Oct 24 2015 02:34
def debug(*); end? :trollface:
Jason Frey
@Fryguy
Oct 24 2015 02:34
TROLOLOL
Joe Rafaniello
@jrafanie
Oct 24 2015 02:34
lol, that's amazing
Jason Frey
@Fryguy
Oct 24 2015 02:35
It's still enormous @ 444MB RSS...and the best part is I can't find why in the heap dump
If I add up all the memsize in the heap dump at that point it's only 70MB
some T_DATA must he holding a TON of stuff
Matthew Draper
@matthewd
Oct 24 2015 02:36
Or it's just been freed by that point
Jason Frey
@Fryguy
Oct 24 2015 02:36
I GC.start before collecting that value
Matthew Draper
@matthewd
Oct 24 2015 02:37
Yeah… RSS reflects peak allocation, but memsize is current
Jason Frey
@Fryguy
Oct 24 2015 02:37
oh fair enough
I forgot :flushed:
Matthew Draper
@matthewd
Oct 24 2015 02:38
(unless you get freakishly lucky and manage to actually release a slab)
Joe Rafaniello
@jrafanie
Oct 24 2015 02:38
It's amazing the stuff we're finding with
allocation tracing and heap dumps
Nice find , I'm sure there's more wtfs we can find and fix
Jason Frey
@Fryguy
Oct 24 2015 02:40
believe it or not I found it accidentally
Matthew Draper
@matthewd
Oct 24 2015 02:41
That seems to be a bit of a theme too :)
Jason Frey
@Fryguy
Oct 24 2015 02:42
haha
here's my logging if it helps
I, [2015-10-23T21:02:49.653556 #86731]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>86731, :memory_usage=>41000960, :memory_size=>2604572672, :percent_memory=>"0.2", :percent_cpu=>"27.2", :cpu_time=>0, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:02:49.983337 #86731]  INFO -- : XXX DUMP BEFORE waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151023-86731-16o54b9.json
I, [2015-10-23T21:02:49.989378 #86731]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>86731, :memory_usage=>41046016, :memory_size=>2604572672, :percent_memory=>"0.2", :percent_cpu=>"82.0", :cpu_time=>60, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:12.823816 #86731]  INFO -- : XXX DUMP AFTER handsoap response: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151023-86731-1nzeaeo.json
I, [2015-10-23T21:03:12.832673 #86731]  INFO -- : XXX MEMORY AFTER handsoap response:  {:pid=>86731, :memory_usage=>564097024, :memory_size=>3148836864, :percent_memory=>"3.3", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:12.837786 #86731]  INFO -- : XXX MEMORY BEFORE parse_response:    {:pid=>86731, :memory_usage=>564097024, :memory_size=>3148836864, :percent_memory=>"3.3", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:12.842780 #86731]  INFO -- : XXX MEMORY AFTER response.document:  {:pid=>86731, :memory_usage=>564097024, :memory_size=>3148836864, :percent_memory=>"3.3", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:12.893085 #86731]  INFO -- : XXX MEMORY AFTER doc.xpath.first:    {:pid=>86731, :memory_usage=>564097024, :memory_size=>3148836864, :percent_memory=>"3.3", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:41.972712 #86731]  INFO -- : XXX MEMORY AFTER unmarshal response: {:pid=>86731, :memory_usage=>1453654016, :memory_size=>4105588736, :percent_memory=>"8.5", :percent_cpu=>"100.0", :cpu_time=>3120, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:03:58.563674 #86731]  INFO -- : XXX DUMP AFTER waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151023-86731-7dbxcu.json
I, [2015-10-23T21:03:58.575808 #86731]  INFO -- : XXX MEMORY AFTER waitForUpdates:     {:pid=>86731, :memory_usage=>1453817856, :memory_size=>4105588736, :percent_memory=>"8.5", :percent_cpu=>"100.0", :cpu_time=>4140, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:04:03.024298 #86731]  INFO -- : XXX MEMORY AFTER creating the cache: {:pid=>86731, :memory_usage=>1685147648, :memory_size=>4380319744, :percent_memory=>"9.8", :percent_cpu=>"101.5", :cpu_time=>4380, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:04:04.531842 #86731]  INFO -- : XXX MEMORY AFTER "helping" the GC    {:pid=>86731, :memory_usage=>1685147648, :memory_size=>4380319744, :percent_memory=>"9.8", :percent_cpu=>"100.0", :cpu_time=>4500, :priority=>"31", :name=>"ruby"}
I, [2015-10-23T21:04:12.083743 #86731]  INFO -- : XXX DUMP BEFORE waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151023-86731-1w11zqw.json
I, [2015-10-23T21:04:12.095850 #86731]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>86731, :memory_usage=>1447268352, :memory_size=>4140199936, :percent_memory=>"8.4", :percent_cpu=>"100.0", :cpu_time=>4920, :priority=>"31", :name=>"ruby"}
I was focusing on that first memory spike which made no sense to me
I think my favorite part is that there is a line that sets something to nil that "helps" the GC, but it does literally nothing
but then when that method goes way out of scope, then the GC can actually claim like 220 MB..haha
Keenan Brock
@kbrock
Oct 24 2015 02:59
curious for that dump but with sax
Jason Frey
@Fryguy
Oct 24 2015 03:11
ManageIQ/manageiq#5092
Oh I probabl y should put some numbers in the commit message
Matthew Draper
@matthewd
Oct 24 2015 03:13
@Fryguy are you in a position to try a run with my sax patch on top of that?
Jason Frey
@Fryguy
Oct 24 2015 03:13
yes
Matthew Draper
@matthewd
Oct 24 2015 03:14
I'm now seeing some reduction even without killing the debug, so I'm not sure what I was looking at differently before :confused:
Jason Frey
@Fryguy
Oct 24 2015 03:14
hrm
Matthew Draper
@matthewd
Oct 24 2015 03:15
But you're running with a larger environment anyway, so more likely to actually show the truth
Jason Frey
@Fryguy
Oct 24 2015 03:21
OK, updated the PR and commit message with some numbers
gonna try to get my little guy to sleep and then I'll try out the sax patch
poor guy has a fever :/
Keenan Brock
@kbrock
Oct 24 2015 03:22
oh noes
travis looks like it has a fever too
Jason Frey
@Fryguy
Oct 24 2015 03:22
well, my PR should fail if thats hat you mean
Keenan Brock
@kbrock
Oct 24 2015 03:22
that handsoap tag doesn't exist
Jason Frey
@Fryguy
Oct 24 2015 03:22
it needs a tag
Keenan Brock
@kbrock
Oct 24 2015 03:22
y
ok
Jason Frey
@Fryguy
Oct 24 2015 03:23
i can probably backport this to 5.4, even
Keenan Brock
@kbrock
Oct 24 2015 03:23
yes
Jason Frey
@Fryguy
Oct 24 2015 03:23
er, botvinnik <_< >_>
Keenan Brock
@kbrock
Oct 24 2015 03:23
"tomorrow"
Jason Frey
@Fryguy
Oct 24 2015 03:23
haha
thanks @matthewd I'll cut the tag now
Fryguy @Fryguy has to copy that facepalm emoji from @matthewd
Jason Frey
@Fryguy
Oct 24 2015 03:30
(-‸ლ)
oh i forgot I had the tears emoji...could have used it here: ༼ ༎ຶ ෴ ༎ຶ༽
Keenan Brock
@kbrock
Oct 24 2015 03:32
I always thought that was a tesla coil
Jason Frey
@Fryguy
Oct 24 2015 03:32
haha
omg i never noticed...can't unsee
Keenan Brock
@kbrock
Oct 24 2015 03:33
co confused. tears... now i understand. still think it looks like tesla, but i undertand why ppl paste it
that or aliens zapping a mountain
Matthew Draper
@matthewd
Oct 24 2015 03:34
@jvlcek called my facepalm a moose running away from an arrow
Jason Frey
@Fryguy
Oct 24 2015 03:34
hahaha
Jason Frey
@Fryguy
Oct 24 2015 04:17
@matthewd Looks like SAX parser helped quite a bit:
# Without handsoap debug crap and with matthew SAX changes
I, [2015-10-24T00:13:55.734074 #4874]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>4874, :memory_usage=>40951808, :memory_size=>2586746880, :percent_memory=>"0.2", :percent_cpu=>"42.4", :cpu_time=>0, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:13:56.069436 #4874]  INFO -- : XXX DUMP BEFORE waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151024-4874-9948qt.json
I, [2015-10-24T00:13:56.075265 #4874]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>4874, :memory_usage=>41009152, :memory_size=>2586746880, :percent_memory=>"0.2", :percent_cpu=>"77.1", :cpu_time=>60, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:18.980443 #4874]  INFO -- : XXX DUMP AFTER handsoap response: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151024-4874-131bn2j.json
I, [2015-10-24T00:14:18.986215 #4874]  INFO -- : XXX MEMORY AFTER handsoap response:  {:pid=>4874, :memory_usage=>162295808, :memory_size=>2729357312, :percent_memory=>"0.9", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:18.991130 #4874]  INFO -- : XXX MEMORY BEFORE parse_response:    {:pid=>4874, :memory_usage=>162295808, :memory_size=>2729357312, :percent_memory=>"0.9", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:18.996069 #4874]  INFO -- : XXX MEMORY AFTER response.content:   {:pid=>4874, :memory_usage=>162295808, :memory_size=>2729357312, :percent_memory=>"0.9", :percent_cpu=>"100.0", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:19.000849 #4874]  INFO -- : XXX MEMORY AFTER Parser.new:         {:pid=>4874, :memory_usage=>162295808, :memory_size=>2729357312, :percent_memory=>"0.9", :percent_cpu=>"99.5", :cpu_time=>1380, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:41.434277 #4874]  INFO -- : XXX MEMORY AFTER SAX::Parser#parse:  {:pid=>4874, :memory_usage=>910409728, :memory_size=>3512557568, :percent_memory=>"5.3", :percent_cpu=>"100.0", :cpu_time=>2760, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:50.584141 #4874]  INFO -- : XXX DUMP AFTER waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151024-4874-18gahjn.json
I, [2015-10-24T00:14:50.595998 #4874]  INFO -- : XXX MEMORY AFTER waitForUpdates:     {:pid=>4874, :memory_usage=>910417920, :memory_size=>3512557568, :percent_memory=>"5.3", :percent_cpu=>"98.8", :cpu_time=>3300, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:54.888291 #4874]  INFO -- : XXX MEMORY AFTER creating the cache: {:pid=>4874, :memory_usage=>936353792, :memory_size=>3546116096, :percent_memory=>"5.5", :percent_cpu=>"101.6", :cpu_time=>3540, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:14:56.241458 #4874]  INFO -- : XXX MEMORY AFTER "helping" the GC    {:pid=>4874, :memory_usage=>936386560, :memory_size=>3546116096, :percent_memory=>"5.5", :percent_cpu=>"100.0", :cpu_time=>3660, :priority=>"31", :name=>"ruby"}
I, [2015-10-24T00:15:02.408679 #4874]  INFO -- : XXX DUMP BEFORE waitForUpdates: /var/folders/y3/p3qvt8mj7v36kg5m6_mfdfgm0000gn/T/rubyheap20151024-4874-1ajhpt4.json
I, [2015-10-24T00:15:02.418102 #4874]  INFO -- : XXX MEMORY BEFORE waitForUpdates:    {:pid=>4874, :memory_usage=>936423424, :memory_size=>3547176960, :percent_memory=>"5.5", :percent_cpu=>"100.0", :cpu_time=>4020, :priority=>"31", :name=>"ruby"}
I did not do a refresh...just priming, so I didn't verify the contents of the cache
Keenan Brock
@kbrock
Oct 24 2015 04:18
will removing the "dump after hand soap" debug to the file help things?
Jason Frey
@Fryguy
Oct 24 2015 04:19
Well, that's my ObjectSpace dump...I don't think that introduces much memory overhead
It's also a GC.start there
Keenan Brock
@kbrock
Oct 24 2015 04:19
k. sax is nice
Matthew Draper
@matthewd
Oct 24 2015 04:19
I was only running on the one small environment, but I had run the DOM & SAX parse in parallel and confirmed their hashes matched, so I do have some basis to believe it's correct
Jason Frey
@Fryguy
Oct 24 2015 04:19
cool
so that is like 500MB savings
granted I have object allocation tracing on and other stuff, so it might be a bit inflated
alright all, I'm off to bed :sleepy:
oh, wanted to mention that the XML is only like 40MB
for perspective
I can extract that and dump it somewhere if it helps
it might make @akrzos happy if I stop pounding the large vcsim :)
Matthew Draper
@matthewd
Oct 24 2015 04:23
Yeah… but considering the "2 char string == 40 bytes minimum, 228 bytes as VimString" thing, we're always going to have some expansion factor :)
Jason Frey
@Fryguy
Oct 24 2015 04:23
yup
Matthew Draper
@matthewd
Oct 24 2015 04:25
I'll have to come up with a better way to override the handsoap response handling, that doesn't globally monkey-patch it away, if we're to actually do something like my SAX thing
Jason Frey
@Fryguy
Oct 24 2015 04:25
yeah
alright...goodnight all (afternoon @matthewd)
Matthew Draper
@matthewd
Oct 24 2015 04:26
:wave: