@bdunne thanks for the polite reminder that this stuff is hard
@kbrock untangle that
require spaghetti
a pie-in-the-sky thought: if
type columns stored the ancestors chain (something like VmOrTemplate>Vm>Providers::Infra::Vm>Providers::Infra::Ovirt::Vm), queries like Vm.all could be based on prefix (LIKE 'VmOrTemplate>Vm>%'), without having to know all descendants. descendant loader could go away!
downside (besides being a major Rails change): inserting or otherwise changing ancestors would require a migration.
hmm, that's not very different from persisting the descendants.yml somewhere into the DB.
but you don't need a migration to add descendants, prob. the most common case.
there are other ways (e.g. a "types" table storing all ancestor-descendant relations, and queries becoming joins through it)...
but you don't need a migration to add descendants, prob. the most common case.
there are other ways (e.g. a "types" table storing all ancestor-descendant relations, and queries becoming joins through it)...
closer to reality: if we care about startup speed, maybe instead of actually loading all descendants before a query, we could just report to ActiveRecord what the descendant names are (and they'd autoload lazily, only if/when such records are constructed)?
anyway, I'm surprised we had to make this thing and it's not solved in Rails... STI + autoloading just don't combine well.
say, are we planning to use Bootsnap?
it also scans sources, and caches bytecode — I wonder if that it might have enough data to figure out descendants. And if we must maintain a crazy caching hack, Bootsnap might be a good place to upstream it...
it also scans sources, and caches bytecode — I wonder if that it might have enough data to figure out descendants. And if we must maintain a crazy caching hack, Bootsnap might be a good place to upstream it...
and could Bootsnap + full eager loading be fast enough to just forget about autoloading!?
@cben Starting at a leaf subclass, everything is fine. Rails knows how to autoload all the way down to the base class. But if you start at the base class, rails won't auto-load all the way up. For example:
# Without descendant loader
irb(main):001:0> VmOrTemplate.descendants.collect(&:name)
=> []
irb(main):002:0> Vm
=> Vm(id: integer, ....
irb(main):003:0> VmOrTemplate.descendants.collect(&:name)
=> ["Vm"]# With descendant loader
irb(main):001:0> VmOrTemplate.descendants.collect(&:name)
=> ["Vm", "MiqTemplate", "VmServer", "ManageIQ::Providers::InfraManager::Vm", "ManageIQ::Providers::CloudManager::Vm", "VmXen", "ManageIQ::Providers::Redhat::InfraManager::Vm", "ManageIQ::Providers::Microsoft::InfraManager::Vm", "ManageIQ::Providers::Vmware::InfraManager::Vm", "ManageIQ::Providers::Amazon::CloudManager::Vm", "ManageIQ::Providers::Azure::CloudManager::Vm", "ManageIQ::Providers::Google::CloudManager::Vm", "ManageIQ::Providers::Openstack::CloudManager::Vm", "ManageIQ::Providers::Vmware::CloudManager::Vm", "ManageIQ::Providers::InfraManager::Template", "ManageIQ::Providers::CloudManager::Template", "ManageIQ::Providers::Redhat::InfraManager::Template", "ManageIQ::Providers::Microsoft::InfraManager::Template", "ManageIQ::Providers::Vmware::InfraManager::Template", "TemplateXen", "ManageIQ::Providers::Openstack::InfraManager::Template", "ManageIQ::Providers::Amazon::CloudManager::Template", "ManageIQ::Providers::Azure::CloudManager::Template", "ManageIQ::Providers::Google::CloudManager::Template", "ManageIQ::Providers::Openstack::CloudManager::Template", "ManageIQ::Providers::Vmware::CloudManager::Template", "ManageIQ::Providers::Openstack::CloudManager::VolumeSnapshotTemplate", "ManageIQ::Providers::Openstack::CloudManager::VolumeTemplate"]
The official rails solution is to eager-load everything
But we don't want enormous worker processes that don't use 80% of the loaded code
Also, constantizing a leaf subclass only loads that branch of the descendant tree. i.e. Constantizing
ManageIQ::Providers::InfraManager::Vm won't load ManageIQ::Providers::CloudManager::Vm
@bdunne but I think I did discover 1 thing: If
Only caviot is searching for all
VmOrTemplate.all had no filter, and Vm.all only searched for template = false, then it will not need to know the subclasses. All other searches will be from the class it is searching - so it should work just fine.Only caviot is searching for all
ManageIQ::Providers::CloudManager::Vm. Not sure how valid this is.
Yes, we do not want to load all classes into memory. Especially if we are in an OpenShift process. But it seems like there may be a simpler solution.
Writing a boot process that parses ruby files to determine the subclasses and then cache them seems like something better done in ruby's core.
And checking file mtimes to determine if the cache is correct is quite complicated.
Writing a boot process that parses ruby files to determine the subclasses and then cache them seems like something better done in ruby's core.
And checking file mtimes to determine if the cache is correct is quite complicated.
Yeah, that's a good point @kbrock but honestly, unless we can pinpoint clear problems we can't mitigate, it will continue to not be on the radar. Most of our rails boot process is not doing the sti loader. I've found it's mostly parsing routes, parsing localization catalogs, etc... then of course seeding (for the MIQ Server process)
Fair enough. I would like to configure which languages are supported, and which providers are supported.
My proposals for removing seating and have not had much success. So I am targeting my next pain point.
Seeding
Maybe focusing on visibility into our processes ishould be my main goal
@kbrock I know it's not the case for
VmOrTemplate, but.. There are several classes (may or may not be AR based) that can be instantiated based on UI selections. In some cases, there is a drop-down in the UI to choose the thing based on something like Thing.descendants.collect(&:display_name). All descendants of Thing are valid choices. There may not yet be any Things in the database, or may not be all types of Things in the database yet. In these cases I believe our only choice is DescendantLoader or eager-load everything.
@bdunne GREAT use case. thanks
To follow onto that point, the Vm being a template = false is a very specific use case. DescendantLoader solves the general use case. We can't always come up with a tailored query for each of the classes that have descendants
Incidentally 72 / 323 tables have the type column (implying STI, and possibly the descendants problem)
so I guess my question with this is why we went with the custom
DescendantLoader hack in the first place? Since we usually air on the argument of "let's do this the Rails way" in general?
yeah...and also if any team were to introduce new tables with STI, they would be required to know this esoteric issue and solve it (and reviewers would have to always be on the lookout for it)
the only thing I can think of for "why" is for faster boot times, which only seems valid only up to a point
we initially did it differently (can't remember anymore how, but I thikn it involved ensuring a mixin was present), and then matthewd solved it generically
he tried to convince Rails core to take it, but it's a gross hack and they didn't want it
still really doesn't answer the "why"... (and "why not just
eager_load")
but even they couldn't figure out how to solve it, so they just said "meh if you're eager loading it's solved, so whatevs"
"why" they didn't take it, or "why" the issue happens at all?
this to me seems like a workaround to eager loading
it sort of is, but even in "normal" Rails installation you don't eager load in dev or test and the issue still presents itself there
it's technically a problem with "autoload"...we just happen to use autload instead of eager load in production
so we could in theory just eager load in dev and test then, right?
yup
which would then make boot times longer for @kbrock ;)
not to mention the memory aspects :)
right, but we just get to those high memory situations eventually anyway
and the issue isn't with "boot times", it is with "on first load of a query, there is a chance something is being eagerloaded"
skewing a performance benchmark
granted, nobody likes slow boot times
maybe? The memory stuff only happens where you have long running processes (typically production)...if I'm firing up a Rails console why would I want to eager load the world
right, technically it happens when someone calls ".descendants" the very first time which is typically on the very first query of an STI model
so, basically almost immediately the first thing anyone "does" with a Rails console :)
if I'm firing up a Rails console why would I want to eager load the world
making this point kinda moot
now you lost me
DescendantLoader does not do an eager load...it doesn't "load the world" in the same sense
well, I was going to do a quick test show that switching to eager loading is effectively the same thing as doing
/bin/rails c; Vm.first with descendant loader, but turns out we have actually busted eager loading in our application
or at least in my current setup
interesting
breaks on trying to load
Hawkular::MiddlewareManager::Inventory, for what it is worth
but not worth me solving now
very interesting....wonder if there's a include_concern type bug there
(stupid question...how do you enable eager loading?)
when into
config/environments/development.rb and switched the eager_load and cache_classes vals to true
:+1:
@NickLaMuro think there is no
inventory.rb stub file
module ManageIQ::Providers
class Hawkular::Inventory::Collector::MiddlewareManager
...
end
endInventory? is that a module?
annoying that they do the lazy class definition - all on 1 line
one of my bet peeves in ruby...
but in other news... turns out if you comment out all of
MiqServer#monitor you still leak a bit of memory
@jrafanie ^
@NickLaMuro over how long a period?
so my thought with that is we might have an issue with settings
@jrafanie only 12 hours
are you palying with the ruby version?
wonder if you change the ruby version if it will go away
nope, just commenting out lines on an appliance
also wonder if you can drop the gem versions and try again
the other thought though is it might be something in the
Settings code
using the version of ruby / gems that weren't leaking
since that is still used in
monitor_poll
@NickLaMuro interesting... I wish we could get it to definitively leak faster
MiqServer#monitor isn't the looping code by the way
@jrafanie I might just try setting up a loop that just keeps checking
Settings
I have an idle appliance running for an hour or two and it's roughly the same RSS as before
it is a slow leak, for what it is worth
is that really a leak? If the GC is never invoked (i.e. you don't run out of live slots), then it will never clean up, and yeah RSS will keep going up
hard to say after only running it for such a short amount of time
Another dumb idea I had was to add a
GC.start in the server process roughly every 30-60 seconds. From your logging @NickLaMuro, sometimes it's 4-5 minutes between full GCs(major_gc_count gets incremented)
it's hard to say though if it takes several hours to reliably call it a leak
@NickLaMuro I got past the hawkular issue, but the next issue with eager load is
/Users/jfrey/.gem/ruby/2.4.2/bundler/gems/manageiq-providers-nuage-a1f64a1cc408/app/models/manageiq/providers/nuage/network_manager/event_catcher/messaging_handler.rb:1:in `<top (required)>': uninitialized constant Qpid (NameError)
which makes sense, but :/
@Fryguy it needs a
require "qpid_proton"
which we can't do, because qpid_proton is optional
and it is a subclass of a global scope
well, I build the gem
yup
and made it non-optional
but not able to require it
bundle exec irb
which makes sense, but :/
ended up just commenting out that one and moved on
wait
yup that's what I figured I'd do
does it make sense to modify our code (put in PRs) to make this work?
eventually, maybe
this looks like a 1 day exercise and a number of changes
I ended up creating a bunch of rb files for each tier of the requires
it fixed a few things
don't know what that means
when the requires failed, I created a ruby file with the package name
it tended to resolve it correctly
did you get past the consumption one?
got to:
manageiq-providers-vmware/app/models/manageiq/providers/vmware/infra_manager/metrics_fetcher_worker.rb:1:in
'<top (required)>': uninitialized constant ManageIQ::Providers::BaseManager::MetricsFetcherWorker (NameError)
ah, ok..I'm not hacking them per se but finding actual solutions
or at least something I can open up as an issue in each repo
cool. GL
some of them are straight up bugs like the one in consumption
sweet
er - yea
I remember that heroku required everything
would find a lot of problems just in first boot
if only there were a ruby like language that compiled and found problems ... ;)
@kbrock what's a metrics_fetcher_worker?
aaaahhhh
thanks
lol
;)
@agrare delete it?
you're probably on a local branch
its not in master
we're not doing that ever. right?
it was not in git at all. right
@agrare thanks so much. I totally didn't see the problem there
we had some branches for it I thought
probably
oh that consumption issue was "fixed" a week or so ago and by "fixed" I mean they deleted the code haha
bin/update for me :/
ok, I'm through the issues (only 2)
now to disable descendant loader
"And this, ladies and gentlemen, has been a lesson in how to distract @Fryguy."
:squirrel:
"Tune in next week when we explore how to exploit this distraction into getting him to do work for you"
I was more interested in the fact that you couldn't eager load which to me implied "uh oh bugs"
HOLY S---!! SUCCESS!!!1!
found way to reproduce the leak with a script!
O_O
it is with
Benchmark.realtime_block
????
:trophy:
really? wow
need to let it run longer to confirm, but let me get show you some output... getting some stuff together... hold plox
# loop_monitor.rb
require 'sys-proctable'
loop do
puts Sys::ProcTable.ps(ARGV[0].to_i).rss
sleep 5
end
puts "PID: #{Process.pid}"# loop_test_1.rb
require 'config/environment.rb'
puts "starting loop..."
loop do
::Settings.server.monitor_poll.to_i_with_method
sleep 0.5
end# loop_test_2.rb
puts "PID: #{Process.pid}"
require 'config/environment.rb'
puts "starting loop..."
def monitor
# intentional no-op
end
loop do
_dummy, timings = Benchmark.realtime_block(:total_time) { monitor }
sleep 0.5
end
holly cow
interesting
that is very short - (aka very cool)
but that doesn't show up in the ruby heap?
Please throw a GC in there to confirm
it's always going to increase until it hits GC thresholds
mmk
maybe I shoudl tweak that to not do a query, in case the query is part of the numbers
Vm.all.to_sql
ohh...good idea
I thought eager load would have been much higher
I wonder the difference in filesystem accesses. (mac - cheap, in a vm, wonder)
note that I am completely ignoring the caveat that if you use eager_load you can no longer reload classes in developement
yes, eager_load is not a long term solution
it's probably more the performance of RipperRubyParser vs just loading a class (for all files)
dammit...I deleted my comment :point_up: :angry:
but .to_sql is about the same numbers...
DescendantLoader uncached:
bundle exec rails r 'Vm.all.to_sql' 48.99s user 2.29s system 99% cpu 51.430 totalDescendantLoader cached:
bundle exec rails r 'Vm.all.to_sql' 8.07s user 2.03s system 98% cpu 10.207 totalDescendantLoader disabled and eager_load enabled (with fixes):
bundle exec rails r 'Vm.all.to_sql' 11.28s user 2.75s system 99% cpu 14.138 total
@NickLaMuro
loop_test_2.rb needs a loop?
huh? are you saying it doesn't have one?
loop do
_dummy, timings = Benchmark.realtime_block(:total_time) { monitor }
sleep 0.5
end
looks like a loop to me
aah
me too...
that is what
loop does?
ooooh
we monkey patch that
do you think it is our patch?
we monkey patch
loop? Or Benchmark?
(I assume he means we patch realtime_block)
because I was suggesting a few days ago that it could be
Benchmark
@NickLaMuro I'm not seeing a leak there:
[5] pry(main)> loop do
[5] pry(main)* _dummy, timings = Benchmark.realtime_block(:total_time) { monitor }
[5] pry(main)* sleep 1
[5] pry(main)* GC.start
[5] pry(main)* puts MiqProcess.processInfo[:memory_usage]
[5] pry(main)* end
174018560
174018560
174018560
174018560...forever
how long did you wait?
:laughing:
does it matter?
looks like until
forever :smile:
haha :)
yeah duh it says it right there haha
or maybe 1 day before forever
just like the loop :trollface:
-1/12
this was a "short version" of my output:
$ ruby loop_monitor.rb 22621
36418
36418 X 19
36482
36482 X 19
36548
# note, I ctrl-c'd right here to get some stuff
36548 X 32
36614
36614 X 31
36680
...
that said, at the moment, we are about
(left the first one running to help confirm @Fryguy 's theory that this could be invalid)
50X + on 36680...(left the first one running to help confirm @Fryguy 's theory that this could be invalid)
what does the current_realtime have?
(For those who don't knwo the -1/12 thing up there... https://en.wikipedia.org/wiki/1_%2B_2_%2B_3_%2B_4_%2B_%E2%8B%AF and
https://www.youtube.com/watch?v=w-I6XTVZXww )
is it not overwriting the hash but growing
current_realtime will always have a single float (and the thread id but that won't change)
actually technically it will be deleted after the block closes
so empty hash
I'm wondering if realtime_store keeps building up the hash, https://github.com/ManageIQ/manageiq-gems-pending/blob/cafb949f42b2214c1d7551f870a69be0814c1f5d/lib/gems/pending/util/extensions/miq-benchmark.rb#L7-L17
there's not much else going on there that's the only thing that stuck out
or maybe we're never calling
delete_current_realtime
realtime_store is not (should not be) called directly
even so, if there was a leak in Benchmark.realtime_* then all of this would be evidenced in the ruby memory stats, but we are not leaking ruby objects according to earlier investigations
yeah
I'm still in my external fragmentation statement
allocate a lot, store 1 object, unallocate the first lot
continue over an over again, waiting a little time, free that 1 object
external fragmentation could def be an issue
in theory, we've allocated no objects, but the memory is screwed up
the
MALLOC_ARENA_MAX should minimize that, but ¯\_(ツ)_/¯
never occured to me that the benchmark code would be making it that much worse
but per @jrafanie said, using
Well, that allocator has less of an issue for this type of fragmentation
So that may support his hypothesis of "the problem is
jemalloc may fix it...Well, that allocator has less of an issue for this type of fragmentation
So that may support his hypothesis of "the problem is
malloc"
yup, it's worth investigating
that is great @NickLaMuro
welp, looks like @Fryguy 's theory is correct that the
GC.start does clear up the leak...
back to the drawing board... again
sorry...I was hoping you were right :confounded:
might have to let these current VMs curn then over the weekend and not touch them, just to make sure that
GC.start gets called
well, can you allocate something in the loop?
you can dump GC stats on some interval and see if GCs are getting called (and how often for that matter)
x = 500 * [500 * "x"]
in theory, that should just be a minor load and shouldn't do anything
hmm. we allocate 10's of millions of objects in some of these workers - so the 500 may be too trivial
wonder if this minor load will introduce the fragmentation that we need
OMG, don't you people take lunch
ESOMANYMESSAGES
<--- central timezone
:sunglasses:
yeah, I take a late eastern timezone lunch and you're still there ;-)
oh god... I am turning into a emoji user...
isn't an emoji user just a computer user?
I'm not convinced doing a GC.start is fair in a script we're trying to recreate a leak for
We don't GC.start in the server. We do it when there are enough allocations to warrant one.
NickLaMuro @NickLaMuro has just delayed is lunch a bit more...
well, to @Fryguy 's point, after a while, my script stopped leaking, even without the
GC.start in place
The script has to just run long enough and LOG the major_gc_count so that over time, a major GC is done
yeah, I was seeing the same with my Drb tests
it would grow to a high water mark and stay there
if you don't have load in your
monitor, then it will be hard to find a leak
well, the point was simulating the small leak that "might" be there in the graph I shared above
^--- that is with all of monitor commented out
slight amount of growth over time, but because we are unsure of the GC situation, hard to tell if that is only a temp bit of growth
anyway, since @jrafanie is getting on my case about it, time for lunch... back in a bit
Yes, thank you @NickLaMuro. You're not yourself when you're hungry.
I am not going to have a snickers for lunch...
haha
I'm not convinced doing a GC.start is fair in a script we're trying to recreate a leak for
We don't GC.start in the server. We do it when there are enough allocations to warrant one.
Partially agree. Doing a GC forces you to not accidentally claim that a graph that looks like :chart_with_upwards_trend: is automatically a leak. It's very highly probable that the monitor loop ends up GC'ing at some point and putting in a manual GC just "speeds that up". That being said, if you think the issue is more of a small Ruby object with a large memory footprint, then yeah, you wouldn't do that, but I don't think we have any evidence pointing to that kind of situation here (unlike how we most obviously had that in vmware land with the giant XMLs)
Also, if we expect c-based literal leaks, then GC is perfect for that, because it removes all Ruby from the picture and the only thing left has to be mallocs
@NickLaMuro finding any more neat stuff?
no, but I am going to be looking into your theory shortly by modifying
heapfrag to take the dumps I have and if the heap gets fragmented over time
though, I guess we could just look at total heap slots in the
GC.stats to determine that
@NickLaMuro I can't get my appliances to grow miq server processes :shrug: I guess I'll look at other reported logs
It looks like you enable cap and u collector and processor and that's about it
@jrafanie do you have it hooked up to a provider?
yes
a small provider
vmware
I have a broker and everything
Mmk, just checking the obvious.