These are chat archives for ManageIQ/manageiq/performance

24th
Jun 2016
Keenan Brock
@kbrock
Jun 24 2016 13:09
ugh so frustrating. @jrafanie how can you ever make sense of ruby-prof?
Oleg Barenboim
@chessbyte
Jun 24 2016 13:14
@jrafanie the date change for the request was one of the screens eliciting the phrase - "click and go for a coffee break"
Keenan Brock
@kbrock
Jun 24 2016 13:16
@chessbyte is there a coffee break list?
I saw a short list, but when I asked for how to actually perform the items, Jared / support didn't know
Dennis Metzger
@dmetzger57
Jun 24 2016 13:24
i’ve asked for the list numerous times, including during customer calls ….. so far …...
Joe Rafaniello
@jrafanie
Jun 24 2016 13:28
@chessbyte yes, I need to test with @imtayadeway's fix for the miqexpression regression to see if it's still slow on master
I probably need to switch to darga branch for testing... I forgot how big some of the changes on master were
Oleg Barenboim
@chessbyte
Jun 24 2016 13:29
lists are too onerous - once we upgrade them to CF 4.1, I will host regularly recurring BlueJeans/WebEx calls with them to see their pain points first-hand
Joe Rafaniello
@jrafanie
Jun 24 2016 13:31
@chessbyte good idea, I'd love to somehow hook Dajo's team UI automation tests against @akrzos's performance scenarios
I'd bet most screens are really slow for completely non-architecture reasons
Maybe the need to know about "protecting against N+1 queries" is a symptom of an architecture problem but just a little navigation with a populated database would band-aid those N+1 problems quickly
Keenan Brock
@kbrock
Jun 24 2016 13:37
@jrafanie is there a reason to hold off from merging ManageIQ/manageiq#8706 ?
Joe Rafaniello
@jrafanie
Jun 24 2016 13:37
No, it just fell to the bottom of the long list of PRs
Keenan Brock
@kbrock
Jun 24 2016 13:38
we are eating exceptions (interrupts)
so getting rid of these is a big win in my book
ok, so I'll merge
Joe Rafaniello
@jrafanie
Jun 24 2016 13:40
thanks, yeah, I'd rather just let the "but we need to rescue Excepton for ..." issues re-occur on master so we can find a better way
rescuing out of memory errors (without re-raising) is not a good idea
Keenan Brock
@kbrock
Jun 24 2016 13:41
lol
@jrafanie I have tracked down my performance issue down to 2 blocks. you have a minute for a call? (we're time boxed by the meeting. so I can't ramble for too long)
Joe Rafaniello
@jrafanie
Jun 24 2016 13:45
:laughing:
sure, I'll dm you
Joe Rafaniello
@jrafanie
Jun 24 2016 15:56
@imtayadeway your miqexpression fix works for me, thanks! At least now, the service -> requests page comes back quickly for no records found on master
still takes 40 seconds to find maybe 20 service requests with a big db of service/requests
with a local db and dedicated hardware
Tim Wade
@imtayadeway
Jun 24 2016 15:58
Yay! I guess accidentally introducing a performance regression is as easy as accidentally optimizing one? ;)
Joe Rafaniello
@jrafanie
Jun 24 2016 15:59
haha
nice
Tim Wade
@imtayadeway
Jun 24 2016 15:59
40 seconds still sounds painful though!
Joe Rafaniello
@jrafanie
Jun 24 2016 16:05
interesting
Nick LaMuro
@NickLaMuro
Jun 24 2016 16:11
makes sense, IO is never free
hrmm.... IO probably wasn't the right term... STDOUT?
regardless, seems like something worth testing
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:15
So I am looking at vm_infra/explorer, and it looks like more MiqExpression stuff... :(
Tim Wade
@imtayadeway
Jun 24 2016 17:19
:running:
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:21
well, I have to double check that I have your fix in place as well, which I don't think I do
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:30
Yeah, this one is a good one... 140sec screen....
Joe Rafaniello
@jrafanie
Jun 24 2016 17:32
@NickLaMuro I'm finding that stackprof is the most useful so far
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:33
Alright, I will try wiring that up
I have been able to get ruby-prof to process it for me though, which is nice
Joe Rafaniello
@jrafanie
Jun 24 2016 17:33
vm_infra/explorer is probably nearly all tree building that @Fryguy was looking at
did you take lunch? Maybe I can show you the rbac stuff i'm seeing on the services -> requests, click some conditions, click apply, and get :coffee:
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:34
sure, we can take a look
Joe Rafaniello
@jrafanie
Jun 24 2016 17:35
it's lunch time there, let me know when you're ready
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:35
meh, lunch time is relative for me ;)
Keenan Brock
@kbrock
Jun 24 2016 17:36
@NickLaMuro for testing that page:
  1. go to the page <== ignore these numbers
  2. refresh the screen <== very different numbers
  3. clicking next page / resort (without the tree view) <== very different numbers
hmm - for testing any page really
also mini-rack-profiler is useful for those pages as well
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:37
right, I did it again for that page and got similar numbers in time though
it dropped by about 10 sec with the classes being cached and whatnot
Keenan Brock
@kbrock
Jun 24 2016 17:38
+1

also, joe doesn't like this but I do:

::RubyProf::CallStackPrinter => lambda() { "#{Time.now.strftime("%H:%M:%S")}-call_stack.html" }

more files, but refreshes and stuff won't mess you up

Nick LaMuro
@NickLaMuro
Jun 24 2016 17:39
Yeah, I have that in there
Joe Rafaniello
@jrafanie
Jun 24 2016 17:39
hehe, I like many things ;-)
Keenan Brock
@kbrock
Jun 24 2016 17:39
;)
joe - though you only wanted 1 file
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:40
# Enable ruby-prof for profiling

if ENV['RUBY_PROF']
  output = Rails.root.join('tmp/rack_ruby_prof')
  puts "** Rack::RubyProf is enabled, each request will dump to '#{output}'."
  puts "** Unset RACK_RUBY_PROF to turn off profiling."

  begin
    require 'ruby-prof'
  rescue LoadError
    puts "Failed! Please make sure ruby-prof is in your Gemfile."
  else

    call_stack_filename = lambda {
      timestamp = Time.now.strftime("%Y%m%d%H%M")
      "#{timestamp}-call-stack.html"
    }

    Rails.application.config.middleware.use Rack::RubyProf,
      :path       => 'tmp/ruby-prof',
      :printers   => {::RubyProf::CallStackPrinter => call_stack_filename},
      :only_paths => [%r{service/explorer}]
  end
end
^ what my config/intializers/ruby-prof.local.rb looks like
heh, just noticed (because I pasted that there) that ruby-prof wasn't even running on the page... because I didn't have the ENV var... oops
so that is 140 without ruby prof running :disappointed:
Oleg Barenboim
@chessbyte
Jun 24 2016 17:48
@NickLaMuro so you have to only improve it 14-fold to get to the 10-second mark - a bad place to be UI-wise, but MUCH better than what you are seeing
Nick LaMuro
@NickLaMuro
Jun 24 2016 17:57
Hey, some people really like coffee...
Jason Frey
@Fryguy
Jun 24 2016 18:01
I do :)
Joe Rafaniello
@jrafanie
Jun 24 2016 19:07
OMG WAT!!!!
@NickLaMuro and I just found the dumbest thing ever
Jason Frey
@Fryguy
Jun 24 2016 19:07
yay!
I love "dumbest thing ever"s
Nick LaMuro
@NickLaMuro
Jun 24 2016 19:07
silver bullet for the win
Jason Frey
@Fryguy
Jun 24 2016 19:08
I knew there were some in there haha
spill it
Joe Rafaniello
@jrafanie
Jun 24 2016 19:08
here you go...
diff --git a/app/controllers/miq_request_controller.rb b/app/controllers/miq_request_controller.rb
index 4baee6d..384208f 100644
--- a/app/controllers/miq_request_controller.rb
+++ b/app/controllers/miq_request_controller.rb
@@ -466,7 +466,7 @@ class MiqRequestController < ApplicationController
       cond.push("or" => a_s.collect { |s| {"=" => {"value" => s, "field" => "MiqRequest-approval_state"}} })
     end

-    cond.push("or" => request_types_for_model.keys.collect { |k| {"=" => {"value" => k.to_s, "field" => "MiqRequest-resource_type"}} })
+    cond.push("or" => request_types_for_model.keys.collect { |k| {"=" => {"value" => k.to_s, "field" => "MiqRequest-type"}} })
Nick LaMuro
@NickLaMuro
Jun 24 2016 19:08
basically we wer sorting by a virtual column when we could have sorted by an actual column
because they are basically the same thing...
Joe Rafaniello
@jrafanie
Jun 24 2016 19:08
it goes from :coffee: time to 1-2 seconds
Dennis Metzger
@dmetzger57
Jun 24 2016 19:09
:clap:
Jason Frey
@Fryguy
Jun 24 2016 19:09
wha? resource_type and type are not both real columns?
Joe Rafaniello
@jrafanie
Jun 24 2016 19:09
nope
Nick LaMuro
@NickLaMuro
Jun 24 2016 19:09
noooooooo00000ooope
Jason Frey
@Fryguy
Jun 24 2016 19:09
WAAAAAAAAAAAAAATTT
that is insanely confusing
Joe Rafaniello
@jrafanie
Jun 24 2016 19:10
class  MiqRequest

  virtual_column  :resource_type,        :type => :string

  def resource_type
    self.class.name
  end
end
Nick LaMuro
@NickLaMuro
Jun 24 2016 19:11
we change the self.resource_type method to be something like:
def resource_type
  raise "Hey... are you sure you just can't use the `type` column here :paperclip:" if Rails.env.development?
  self.class.name
end
Joe Rafaniello
@jrafanie
Jun 24 2016 19:11
it turns out self.class.name == the type column
Jason Frey
@Fryguy
Jun 24 2016 19:11
awesome find @jrafanie and @NickLaMuro ... Also, @gmcculloug can we please rename resource_type to something else?
resource_type is always a polymorphic column name
Joe Rafaniello
@jrafanie
Jun 24 2016 19:12
yeah, thankfully @NickLaMuro told me that's not a real column
This message was deleted
Joe Rafaniello
@jrafanie
Jun 24 2016 20:10
ManageIQ/manageiq#9443
@dmetzger57 that PR is totally backportable to older releases
Oleg Barenboim
@chessbyte
Jun 24 2016 20:17
why do we have a virtual column that has the same value as a real column??????
Keenan Brock
@kbrock
Jun 24 2016 20:18
@chessbyte reference?
Oleg Barenboim
@chessbyte
Jun 24 2016 20:18
ManageIQ/manageiq#9443
Keenan Brock
@kbrock
Jun 24 2016 20:19
hmm. type is the type of the miq request and resource_type is the type of the resource it points to. these seem different
nice find @NickLaMuro
I see type and request_type both in miq_requests
Jason Frey
@Fryguy
Jun 24 2016 20:23
Let me clarify...why would we use a virtual column name for something that in many other tables is a real column
Keenan Brock
@kbrock
Jun 24 2016 20:24
let me clarify, I see that column in the database
Jason Frey
@Fryguy
Jun 24 2016 20:24
then that's even MORE screwy o_O
Keenan Brock
@kbrock
Jun 24 2016 20:24
lol
ooh
so someone added resource_type into the database which contains type
  def resource_type
    self.class.name
  end
Jason Frey
@Fryguy
Jun 24 2016 20:26
btw, resource_type is not a column (perhaps you saw request_type, which is different?)
Keenan Brock
@kbrock
Jun 24 2016 20:26
ooh - I see there is request_type not resource_type
ok, we have 2 options
  1. replace the column in the query
  2. teach the db how to use that column in sql
Jason Frey
@Fryguy
Jun 24 2016 20:26
so, given that, a virtual_column was created with a name that is so commonly a real column in other tables that it makes it confusing
@kbrock 2 would fix the performance issue directly, but not remove the confusion of having a column named that
Keenan Brock
@kbrock
Jun 24 2016 20:27
correct
if there is backwards compatibility issues
Jason Frey
@Fryguy
Jun 24 2016 20:27
right, and 1 avoids using the method
Keenan Brock
@kbrock
Jun 24 2016 20:28
and 3 deletes the method and virtual column ;)
Jason Frey
@Fryguy
Jun 24 2016 20:28
option 3. rename the method to something else if caller still need it
Keenan Brock
@kbrock
Jun 24 2016 20:28
lol
Jason Frey
@Fryguy
Jun 24 2016 20:28
haha
Keenan Brock
@kbrock
Jun 24 2016 20:28
scarry - the world is converging in a crazy place
Jason Frey
@Fryguy
Jun 24 2016 20:28
it's up to @gmcculloug ... I don't understand its purpose at all
maybe @bdunne might know
Keenan Brock
@kbrock
Jun 24 2016 20:29
yea - that is on @gmcculloug :bus:
need an emoji with a bus and a person under it
Jason Frey
@Fryguy
Jun 24 2016 20:31
:bus:
:runner:
Keenan Brock
@kbrock
Jun 24 2016 20:31
lol
@Fryguy services screen. the tree builder is N+1 fetching services. and it can be fetched using a subtree search. would be a very big win.
Yesterday people said you were on this. is this right?
Jason Frey
@Fryguy
Jun 24 2016 20:33
yes we are on it
but subtree search is misleading in how much speedup
that tree has 9000 nodes at the root level
Keenan Brock
@kbrock
Jun 24 2016 20:33
how so?
so we are not fetching all the children?
Jason Frey
@Fryguy
Jun 24 2016 20:34
we are
the N+1 was mostly fixed by @jrafanie's PR where we go get the picture for each one
Keenan Brock
@kbrock
Jun 24 2016 20:34
well, just the picture of the roots
Jason Frey
@Fryguy
Jun 24 2016 20:34
right and 99% of the records are roots
Keenan Brock
@kbrock
Jun 24 2016 20:34
but we were still fetching the services one by one
aah
Jason Frey
@Fryguy
Jun 24 2016 20:35
yes, that part is trickier because of the way ancestry works
Keenan Brock
@kbrock
Jun 24 2016 20:35
aah, I remember an issue around this
Jason Frey
@Fryguy
Jun 24 2016 20:35
I put together an alternative but haven't had a chance to run through with @NickLaMuro and @jrafanie yet
Keenan Brock
@kbrock
Jun 24 2016 20:35
ok - as long as you are covered. let me know if you need another chef
Jason Frey
@Fryguy
Jun 24 2016 20:35
thanks!
Nick LaMuro
@NickLaMuro
Jun 24 2016 21:58
Time to pull a Keenan and say "Time for lunch!"
Jason Frey
@Fryguy
Jun 24 2016 21:58
LOLOLOL
Keenan Brock
@kbrock
Jun 24 2016 21:58
lol
I ate at 3pm
Jason Frey
@Fryguy
Jun 24 2016 21:58
oh...early lunch?
Keenan Brock
@kbrock
Jun 24 2016 21:58
but yea, the kids are goign to ask for dinner about now. thanks
lol
Nick LaMuro
@NickLaMuro
Jun 24 2016 21:59
heh
Keenan Brock
@kbrock
Jun 24 2016 21:59
the worst is when it is 2AM and you say, gosh, should eat breakfast
Nick LaMuro
@NickLaMuro
Jun 24 2016 21:59
LOL
Keenan Brock
@kbrock
Jun 24 2016 21:59
and the "why do I have such a headache?"
Joe Rafaniello
@jrafanie
Jun 24 2016 21:59
hehe
Keenan Brock
@kbrock
Jun 24 2016 21:59
ooh, it has been 30+hours since I've eaten
Joe Rafaniello
@jrafanie
Jun 24 2016 22:00
Yay, ManageIQ/manageiq#9443 is merged, I'm out of here, talk to you all after :fireworks:
Nick LaMuro
@NickLaMuro
Jun 24 2016 22:00
:runner:
Keenan Brock
@kbrock
Jun 24 2016 22:00
just in: fewer calls to MiqPreloader.preload results in a savings for queries
doesn't make total sense to me
includes = {:ext_management_systems => {:hosts => {:ems_cluster => :tags, :tags => {}}}}
includes[:ext_management_systems][:hosts][:storages] = :tags unless options[:exclude_storages]
includes[:ext_management_systems][:hosts][:vms] = :ext_management_system unless options[:exclude_vms]
brings back ~20 fewer records than that in 3 calls
I would have thought that the query count would be 1 + 2 +3 - but it is less
they do something with the ems lookup and the tags
I can see HOW it could be a savings. But I didn't think the code would do that
@Fryguy there are >200 references to resource_type - not sure now many of those are miq_request.resource_type. Do you want me to put together some arel there? or just let is go for now?
Keenan Brock
@kbrock
Jun 24 2016 22:05
will get savings in D but not C (D should optimize miq_expression w/ virtual_columns+arel)