These are chat archives for ManageIQ/manageiq/performance

2nd
Feb 2016
Keenan Brock
@kbrock
Feb 02 2016 13:52 UTC
@dmetzger57 you having fun yet?
Dennis Metzger
@dmetzger57
Feb 02 2016 13:53 UTC
that’s one description
Keenan Brock
@kbrock
Feb 02 2016 13:53 UTC
not having visibility into the sql is tricky. but I do have the timings cut up pretty well
Dennis Metzger
@dmetzger57
Feb 02 2016 13:54 UTC
so you’ve identified where we spend large chunks of time
Keenan Brock
@kbrock
Feb 02 2016 13:54 UTC
yes
Dennis Metzger
@dmetzger57
Feb 02 2016 13:54 UTC
i just run against 10.10.182.120 and was about to do that
Keenan Brock
@kbrock
Feb 02 2016 13:55 UTC
I have the db local
Dennis Metzger
@dmetzger57
Feb 02 2016 13:55 UTC
looking at evm.log and production.log
Keenan Brock
@kbrock
Feb 02 2016 13:55 UTC
have been wrestling with getting my tools running... :(
not having sql is a big hit, but I can annotate methods - so I'm getting pretty granular
Dennis Metzger
@dmetzger57
Feb 02 2016 13:56 UTC
so are there many long running methods or a few nasty long running ones to worry about
Keenan Brock
@kbrock
Feb 02 2016 13:57 UTC
it is dispersed :(
total = 27k
explorer = 26k
feature tree = 25.6k
(I'm diving down)
Dennis Metzger
@dmetzger57
Feb 02 2016 13:58 UTC
whats the unit of measure there “27k"
Matthew Draper
@matthewd
Feb 02 2016 13:58 UTC
k = thousands of ms?
Keenan Brock
@kbrock
Feb 02 2016 13:58 UTC
yes
ugh - waiting for a refresh
ok - so x_build_dynatree = 25.7k
so this is good
then we build a bunch of subtrees
TreeBuilderVmsAndTemplates#tree
6 of them
hmm
has to be a better way
one sec
render = 747
image
y u no post picture :(
Jason Frey
@Fryguy
Feb 02 2016 14:01 UTC
Do you have 6 EMSes?
Keenan Brock
@kbrock
Feb 02 2016 14:01 UTC
sorry -in the future I'll be able to post text
1
hmm
Jason Frey
@Fryguy
Feb 02 2016 14:02 UTC
Interesting... There are multiple trees per accordion
Dennis Metzger
@dmetzger57
Feb 02 2016 14:02 UTC
yea they have 6 providers
Jason Frey
@Fryguy
Feb 02 2016 14:03 UTC
And for whatever reason the UI builds everything in every accordion even if your don't see it
Keenan Brock
@kbrock
Feb 02 2016 14:03 UTC
image
Jason Frey
@Fryguy
Feb 02 2016 14:03 UTC
You could probably save a TON of time by not having it do that
Keenan Brock
@kbrock
Feb 02 2016 14:04 UTC
bringing back every record does hit us
Jason Frey
@Fryguy
Feb 02 2016 14:04 UTC
We have to.... That was fixed to solve a different BZ
It's why that one tree is different
Keenan Brock
@kbrock
Feb 02 2016 14:04 UTC
13k vm, 700 archived, 149 orphaned
Matthew Draper
@matthewd
Feb 02 2016 14:04 UTC
Trying a random 2 year old (say) r-m-p doesn't fix the lack of SQL, btw?
Jason Frey
@Fryguy
Feb 02 2016 14:05 UTC
I'll have to find you the BZ, but I'm not at my laptop at the moment
But the gist is that with that many VMs, open up a lot of folders and other twisty items in the tree, then refresh the page...
Keenan Brock
@kbrock
Feb 02 2016 14:06 UTC
@matthewd rubygems tried master, 0.9.8, 0.1.31
Jason Frey
@Fryguy
Feb 02 2016 14:07 UTC
Because of the nature of the old walking style tree, and the way the UI opens up those twisties on refresh, it would basically N+1 the entire VMs list
Keenan Brock
@kbrock
Feb 02 2016 14:07 UTC
fun fact: changing the sort (so refreshing the right hand side = 576ms
so EVERYTHING is in the left hand side
Jason Frey
@Fryguy
Feb 02 2016 14:08 UTC
So I switched it to a full tree... Also not the most efficient, but it loaded in a few seconds so it was worth it
Keenan Brock
@kbrock
Feb 02 2016 14:08 UTC
yea - on master, with that SQL, it is good
but the sheer quantity of data
and the dom refresh (drawing events)
is expensive for that much data
so while sql is not an n+1, it is a bunch
Jason Frey
@Fryguy
Feb 02 2016 14:08 UTC
I had that much on my original code... It wasn't that bad
Keenan Brock
@kbrock
Feb 02 2016 14:08 UTC
ALSO
sorting in ruby is taking some time
Jason Frey
@Fryguy
Feb 02 2016 14:08 UTC
Something new must be in the way
Matthew Draper
@matthewd
Feb 02 2016 14:09 UTC
@kbrock do you just need to backport @Fryguy's changes from master? Is that feasible?
Keenan Brock
@kbrock
Feb 02 2016 14:09 UTC
those changes are in there
Jason Frey
@Fryguy
Feb 02 2016 14:09 UTC
My changes are already on that version
Which is why I'm confused how suddenly it's bad
Keenan Brock
@kbrock
Feb 02 2016 14:09 UTC
@Fryguy so, the right hand side is taking 500ms
Matthew Draper
@matthewd
Feb 02 2016 14:10 UTC
But master is fine? :confused:
Keenan Brock
@kbrock
Feb 02 2016 14:10 UTC
the left hand side is taking 28000ms
no
master is not fine
if archived is high - it is bad
if orphans is high - it is bad
there is paging for a reason
Matthew Draper
@matthewd
Feb 02 2016 14:10 UTC
master has a different problem (the icon thing)
Jason Frey
@Fryguy
Feb 02 2016 14:10 UTC
Ahhhhh... D
Keenan Brock
@kbrock
Feb 02 2016 14:10 UTC
we are downloading everything
ooh
yes
icon = 75% of problem (4 different icons ;) )
Jason Frey
@Fryguy
Feb 02 2016 14:10 UTC
Archived is not one of those full trees
Matthew Draper
@matthewd
Feb 02 2016 14:10 UTC
Apart from the icons, master is fine?
Jason Frey
@Fryguy
Feb 02 2016 14:10 UTC
Nor is orphaned
Keenan Brock
@kbrock
Feb 02 2016 14:10 UTC
we download ALL of both from the db
all columns of those
Jason Frey
@Fryguy
Feb 02 2016 14:11 UTC
I never got around to updating those trees
Keenan Brock
@kbrock
Feb 02 2016 14:11 UTC
anyway
not the problem today
Jason Frey
@Fryguy
Feb 02 2016 14:11 UTC
Oh wait... Are you saying archived and orphaned are not the problem? I'm confused
Keenan Brock
@kbrock
Feb 02 2016 14:11 UTC
just saying, that the right hand side (20 rows) is 0.5, and the left hand side (13k records) is 28 seconds
right now, it is a minor problem
Matthew Draper
@matthewd
Feb 02 2016 14:12 UTC
On master, when you skipped the icons, the performance was fine.. wasn't it?
Keenan Brock
@kbrock
Feb 02 2016 14:12 UTC
building the trees is the major problem
@matthewd non-icons was 4 seconds (vs 14 seconds) - master
@matthewd but the main grid was only like 300ms - master
Jason Frey
@Fryguy
Feb 02 2016 14:12 UTC
There is an optimization is the VMs and templates tree for the icon
Maybe it's changed or not being leveraged?
Matthew Draper
@matthewd
Feb 02 2016 14:12 UTC
Compared to 30s, 4s sounds like "fine" to me
Alex Krzos
@akrzos
Feb 02 2016 14:13 UTC
@Fryguy The last time the vm_infra page was addressed it was using data that was ~1000 vms
Keenan Brock
@kbrock
Feb 02 2016 14:13 UTC
I guess
Matthew Draper
@matthewd
Feb 02 2016 14:13 UTC
Solve one problem at a time
Jason Frey
@Fryguy
Feb 02 2016 14:13 UTC
@akrzos I tested locally with 10000 ;)
Alex Krzos
@akrzos
Feb 02 2016 14:13 UTC
It has always been a problem when there was 10000
Matthew Draper
@matthewd
Feb 02 2016 14:14 UTC
We can work out whether 4s can be improved later.. right now your priority is surely to identify what's making master much faster than the older branch, and find a way to backport
Jason Frey
@Fryguy
Feb 02 2016 14:14 UTC
Oh really? That's news to me :(
Matthew Draper
@matthewd
Feb 02 2016 14:15 UTC
Otherwise you're doing perf analysis on a 30s request to optimise it from scratch, when we already have a much better performing version sitting in master
Alex Krzos
@akrzos
Feb 02 2016 14:15 UTC
Back on 5.3
87s on sandy bridge hardware
moving to new hardware definitely reduces the rendering timing here
on the db referenced i tested it on sandy bridge vs haswell it was something like 60s vs 30ish seconds
so new hardware can temporary hide the problem
^ 5.4
Keenan Brock
@kbrock
Feb 02 2016 14:19 UTC
ok
5.4:
name, time, time with children, offset from start
      TreeBuilderVmsAndTemplates#tree 466.3 11104.1 +3171.0 
       TreeBuilderVmsAndTemplates#relationship_tree 274.3 10637.8 +3171.0 
        EmsVmware#subtree_arranged  2917.8  2917.8  +3172.0 
        Rbac.search 5942.9  7445.7  +6157.0 
         Rbac.determine_ids_clause  4.4 4.4 +6163.0 
         Rbac.find_targets_with_rbac  1498.4  1498.4  +6174.0
that is pretty consistent across all
since we have 6 vms, we have 2 large ones of those
Alex Krzos
@akrzos
Feb 02 2016 14:20 UTC
I think 5.5 has been the best i've seen with ~10000 vms, something more on the order of 20ish seconds (on Haswell best hardware I have)
Keenan Brock
@kbrock
Feb 02 2016 14:20 UTC
1/3 = arrange, 1/2 = rbac finding targets (which they are already local :( )
Matthew Draper
@matthewd
Feb 02 2016 14:20 UTC
What makes master so much better there?
Keenan Brock
@kbrock
Feb 02 2016 14:20 UTC
@matthewd it is not
we have a few tweaks - I'm not sold that master is any better
Matthew Draper
@matthewd
Feb 02 2016 14:20 UTC
But.. you said master was 4s
Keenan Brock
@kbrock
Feb 02 2016 14:21 UTC
sorry - determine_ids_clause = me dividing up rbac trying to find problems
Matthew Draper
@matthewd
Feb 02 2016 14:21 UTC
There's a single method call that's 6s right there
Keenan Brock
@kbrock
Feb 02 2016 14:21 UTC
@matthewd sorry - forgot headers
Matthew Draper
@matthewd
Feb 02 2016 14:22 UTC
I know what the columns are
Keenan Brock
@kbrock
Feb 02 2016 14:22 UTC
aah - yes, 3s + 7.5s
Matthew Draper
@matthewd
Feb 02 2016 14:22 UTC
Is master 4s, or not?
Keenan Brock
@kbrock
Feb 02 2016 14:22 UTC
dunno
Matthew Draper
@matthewd
Feb 02 2016 14:23 UTC
non-icons was 4 seconds (vs 14 seconds) - master
Keenan Brock
@kbrock
Feb 02 2016 14:23 UTC
ok
different data set
not 6 ems
ems vm count
nil 854
mprdvctis800 811
mprdvctis100 1128
mprdvctis600 1557
mprdvctis300 4154
mprdvctis101 989
mprdvctis301 376
4k isn't very many
Keenan Brock
@kbrock
Feb 02 2016 14:30 UTC
name time child offset
Executing action: explorer 22.1 29741.2 +19.0
VmInfraController#explorer 7.2 29719.1 +38.0
VmInfraController#x_build_dynatree 312.8 25769.1 +39.0
Rbac.search 136.9 141.8 +40.0
TreeBuilderVmsAndTemplates#tree 64.0 1565.8 +182.0
TreeBuilderVmsAndTemplates#tree 50.4 1423.2 +1748.0
EmsVmware#subtree_arranged 656.3 656.3 +1748.0
Rbac.search 301.0 666.4 +2418.0
Rbac.find_targets_with_rbac 364.3 364.3 +2429.0
TreeBuilderVmsAndTemplates#tree 466.3 11104.1 +3171.0
EmsVmware#subtree_arranged 2917.8 2917.8 +3172.0
Rbac.search 5942.9 7445.7 +6157.0
Rbac.find_targets_with_rbac 1498.4 1498.4 +6174.0
TreeBuilderVmsAndTemplates#tree 216.5 9570.2 +14276.0
EmsVmware#subtree_arranged 2696.6 2696.6 +14276.0
Rbac.search 4757.8 6173.4 +17030.0
Rbac.find_targets_with_rbac 1411.6 1411.6 +17044.0
TreeBuilderVmsAndTemplates#tree 0.3 31.3 +23846.0
TreeBuilderVmsAndTemplates#tree 41.8 1282.0 +23877.0
TreeBuilderVmsAndTemplates#relationship_tree 44.3 1240.1 +23877.0
EmsVmware#subtree_arranged 725.3 725.3 +23877.0
Rbac.search 194.3 470.5 +24614.0
Rbac.search 22.8 298.7 +25449.0
Rbac.search 6.0 8.4 +25751.0
Rbac.search 6.7 21.8 +25774.0
Rbac.search 5.4 8.9 +25800.0
hmm, indent not so good
[=>gist] a little better
Joe Rafaniello
@jrafanie
Feb 02 2016 14:32 UTC
Sorry, I'm late to this, @kbrock can you restate your findings... I can't tell if master is faster, how many vms there are and if the breakdown of vm types matters?
is it safe to assume you're doing production mode?
Keenan Brock
@kbrock
Feb 02 2016 14:32 UTC
no
not production mode
jrafanie - 13k vms, 6 Ems, viewing main content on right is < 1 second, building trees on left are up to 10 seconds per ems - 5.4
Joe Rafaniello
@jrafanie
Feb 02 2016 14:34 UTC
is it all vmware?
Keenan Brock
@kbrock
Feb 02 2016 14:34 UTC
great question => yes all vmware
Joe Rafaniello
@jrafanie
Feb 02 2016 14:34 UTC
is this with the reported issue's database or a mockup of what we think they have?
Keenan Brock
@kbrock
Feb 02 2016 14:34 UTC
local database on my machine- exact copy
different version of postgres
Joe Rafaniello
@jrafanie
Feb 02 2016 14:36 UTC
what is the reported version? 5.4? I see 5.5 and master mentioned... curious if you have the total time for the same screen for those 3
Dennis Metzger
@dmetzger57
Feb 02 2016 14:36 UTC
customer version == 5.4.1.0
Joe Rafaniello
@jrafanie
Feb 02 2016 14:37 UTC
I might have missed the high level, I see lots of details but don't see the total time comparison by version
Keenan Brock
@kbrock
Feb 02 2016 14:37 UTC
ooh - yes. I'm on 5.4.z
Joe Rafaniello
@jrafanie
Feb 02 2016 14:37 UTC
ok, so do you have the 5.4, 5.5, master results for the same page in production mode?
(same database)
Keenan Brock
@kbrock
Feb 02 2016 14:38 UTC
getting numbers for 5.4.z
Joe Rafaniello
@jrafanie
Feb 02 2016 14:38 UTC
ok
thanks!
Keenan Brock
@kbrock
Feb 02 2016 14:38 UTC
think dennis said same for 5.5 - verify @dmetzger57 ?
dennis is a true engineer - he is running against real appliances.
Joe Rafaniello
@jrafanie
Feb 02 2016 14:39 UTC
So, production mode then...
Keenan Brock
@kbrock
Feb 02 2016 14:39 UTC
... hold please... :(
Joe Rafaniello
@jrafanie
Feb 02 2016 14:39 UTC
hehe
while I think it's relevant to test slowness in dev mode, it's only relevant if prod and dev exhibit the same slowness ;-)
Keenan Brock
@kbrock
Feb 02 2016 14:40 UTC
yea, first page is always slower, 115s running again
ok, 26s, same profile. 2 ems are hitting us hard
not sure which ones
Dennis Metzger
@dmetzger57
Feb 02 2016 14:43 UTC
I’ve been looking 5.4.1 on a production appliance, I’ve not run with this database on a 5.5 appliance, I’ve run against a 3k VM environment t with a 5.5.2.4-2 appliance which take ~9 seconds to render, I see ~34 seconds on the 5.4.1 with 13k VMs. Need to get the customer DB on 5.5.2.4
Keenan Brock
@kbrock
Feb 02 2016 14:43 UTC
  TreeBuilderVmsAndTemplates#tree    465.8    10370.4    +2953.0    
   TreeBuilderVmsAndTemplates#relationship_tree    443.3    9904.6    +2953.0    
    EmsVmware#subtree_arranged    2553.6    2553.6    +2953.0    
    Rbac.search    5827.2    6907.7    +5776.0    
     Rbac.determine_ids_clause    5.2    5.2    +5783.0    
     Rbac.find_targets_with_rbac    1075.3    1075.3    +5794.0    
READ: numbers are similar, but not so obvious WHERE in rbac it is eating the time
while RBAC is over 50%, it is not 100% :(
I'm going to disect more - thanks all
Joe Rafaniello
@jrafanie
Feb 02 2016 14:46 UTC
@kbrock @dmetzger57 great, yeah... I think once we have comparisons of different versions with the same database, we'll be able to confirm/deny recent changes made it better/worse
Dennis Metzger
@dmetzger57
Feb 02 2016 14:49 UTC
yes - my gut says seeing the 9 seconds for the 3k VMs on 5.5.2 makes me think we’ll be seeing 30 seconds for the customer 13k VMs DB, but until that is validated, no-one knows
Alex Krzos
@akrzos
Feb 02 2016 14:56 UTC
@jrafanie I have two appliances 5.4.4.2 and 5.4.5.0 running that db
I can migrate it to 5.5 and look at the rendering time
do we have instructions on migrating
from 5.4 to 5.5
Joe Rafaniello
@jrafanie
Feb 02 2016 14:56 UTC
yeah, somewhere, let me look
here we go
that links to the 5.4 to 5.5 guide here: https://access.redhat.com/articles/2076193
Alex Krzos
@akrzos
Feb 02 2016 14:59 UTC
excellent bookmarked for the future
Keenan Brock
@kbrock
Feb 02 2016 15:00 UTC
akrzos - or you can rake db:drop db:create db:migrate db:seed - then you'll be up on the latest version
... please don't do that ...
Joe Rafaniello
@jrafanie
Feb 02 2016 15:00 UTC
lol
Alex Krzos
@akrzos
Feb 02 2016 15:03 UTC
5.4 to 5.5 is a different underlying os
rhel 6 to rhel 7
Dennis Metzger
@dmetzger57
Feb 02 2016 15:03 UTC
yea, the number of variables is most impressive
Keenan Brock
@kbrock
Feb 02 2016 15:04 UTC
#protip:
EvmDatabase.seed_primordial unless ENV['SKIP_PRIMORDIAL'] == "true"
speeds up boot BIG TIME
don't worry @jrafanie - I'll wait a few months for that crusade
Joe Rafaniello
@jrafanie
Feb 02 2016 15:11 UTC
Yes @kbrock that's a pain I hate
Keenan Brock
@kbrock
Feb 02 2016 15:11 UTC
have to say - it is working great
just changed to:
ENV['SKIP_PRIMORDIAL'] == "true" ? MiqServer.seed : EvmDatabase.seed_primordial
Joe Rafaniello
@jrafanie
Feb 02 2016 15:11 UTC
primordial includes VmdbDatabase.seed which is not primordial
Keenan Brock
@kbrock
Feb 02 2016 15:11 UTC
heh
Joe Rafaniello
@jrafanie
Feb 02 2016 15:11 UTC
but alas, the UI can't run without it
Keenan Brock
@kbrock
Feb 02 2016 15:12 UTC
well, nothing can run without seeds
anyway
sorry
tangent
"tomorrow"
Joe Rafaniello
@jrafanie
Feb 02 2016 15:12 UTC
:squirrel:
squirrel ;-)
Dennis Metzger
@dmetzger57
Feb 02 2016 15:12 UTC
squirrel chasing ….
Joe Rafaniello
@jrafanie
Feb 02 2016 15:12 UTC
:sparkle:
Keenan Brock
@kbrock
Feb 02 2016 15:12 UTC
;)
well, if you are booting a machine ~50 times in 1 day...
30+seconds => 8seconds
just sayin
Keenan Brock
@kbrock
Feb 02 2016 15:52 UTC
fyi:
Completed 200 OK in 23239.6ms (Views: 152.7ms | ActiveRecord: 1003.9ms)
Oleg Barenboim
@chessbyte
Feb 02 2016 16:15 UTC
23 seconds? wow
Keenan Brock
@kbrock
Feb 02 2016 16:15 UTC
and not an N+1
Oleg Barenboim
@chessbyte
Feb 02 2016 16:18 UTC
@kbrock - please tell me that is before any performance improvements ;-)
Keenan Brock
@kbrock
Feb 02 2016 16:18 UTC
+1
BEFORE
50% in rbac
think it is in object invocation, still trying to track down
Joe Rafaniello
@jrafanie
Feb 02 2016 16:35 UTC
@kbrock context? 23 seconds... what scenario? master/5.5/5.4? What # of vms?
Keenan Brock
@kbrock
Feb 02 2016 16:36 UTC
@jrafanie 13k vms (actual), 5.4.z, local postgres 9.4, logged in as admin, production mode ruby-2.0.0-p643
Oleg Barenboim
@chessbyte
Feb 02 2016 16:37 UTC
@jrafanie would appreciate your help here as customer is escalating this issue
Keenan Brock
@kbrock
Feb 02 2016 16:37 UTC
@chessbyte @jrafanie has been hooking us up
Joe Rafaniello
@jrafanie
Feb 02 2016 16:37 UTC
Sure, how can I help?
Oleg Barenboim
@chessbyte
Feb 02 2016 16:39 UTC
defer to @dmetzger57 and @kbrock on how to help. issue is that drawing some tree is VERY slow - users are complaining
something like 40 seconds in customer's environment
Joe Rafaniello
@jrafanie
Feb 02 2016 16:41 UTC
ok, @dmetzger57 please DM me where I can get the DB
Dennis Metzger
@dmetzger57
Feb 02 2016 16:41 UTC
essentially BZ 1281999, in the customer case going Infrastructure -> Virtual Machines takes over 30 seconds to render
have not seen an N+1 issue
Keenan Brock
@kbrock
Feb 02 2016 16:43 UTC
+1
Dennis Metzger
@dmetzger57
Feb 02 2016 16:43 UTC
specifics to get the DB dumb are in the ticket, as well as access to running 5.4 appliance with this DB
Jason Frey
@Fryguy
Feb 02 2016 16:43 UTC
(I'm sure you are all aware, just remember this is a public channel, so be discreet on details)
Dennis Metzger
@dmetzger57
Feb 02 2016 16:44 UTC
+1
Joe Rafaniello
@jrafanie
Feb 02 2016 16:45 UTC
thanks
Dennis Metzger
@dmetzger57
Feb 02 2016 16:45 UTC
I’ve been reviewing the logs, looking to identify hot spot, run tests on my 5.4 appliance, getting the DB on my 5.5.4-2 appliance to test there
Keenan Brock
@kbrock
Feb 02 2016 16:46 UTC
@jrafanie I gave details on my runtime because many of those are not standard / don't match actual problem. (But I'm able to reproduce just fine)
Joe Rafaniello
@jrafanie
Feb 02 2016 16:46 UTC
Great, thanks.... so, have we confirmed master is exhibiting the same slowdown in the same area?
Dennis Metzger
@dmetzger57
Feb 02 2016 16:47 UTC
I’ve not imported to one of my Master appliances yet, getting that started in parallel with my 5.5.4 appliance
Joe Rafaniello
@jrafanie
Feb 02 2016 16:48 UTC
ok
Dennis Metzger
@dmetzger57
Feb 02 2016 16:48 UTC
the import takes a while
at least in my environment
Keenan Brock
@kbrock
Feb 02 2016 16:48 UTC
heh - a long while
Joe Rafaniello
@jrafanie
Feb 02 2016 16:48 UTC
Have we tried truncating the big tables that aren't important in this screen?
vim_performance_states?
ems_events?
Dennis Metzger
@dmetzger57
Feb 02 2016 16:48 UTC
i have not
Keenan Brock
@kbrock
Feb 02 2016 16:49 UTC
no way - I waited 1/2 an hour to get them into my db ;)
Joe Rafaniello
@jrafanie
Feb 02 2016 16:49 UTC
ok, i'll do that, it's hard to compare things if we have to wait for the db to import each time we make a change
Keenan Brock
@kbrock
Feb 02 2016 16:50 UTC
each time?
aah - change being changing the manageiq version not the code
Dennis Metzger
@dmetzger57
Feb 02 2016 16:52 UTC
I’m relying on snaps on the various versions on the appliance, once the db is imported there’s not much wall clock time required to try things
testing / setting up 5.4.1, 5.5.2 and Master appliances with the DB, waiting for 5.5.2 to finish the import
Joe Rafaniello
@jrafanie
Feb 02 2016 16:54 UTC
is the dump less than 10 GB?
Keenan Brock
@kbrock
Feb 02 2016 16:54 UTC
yes
dump is 1.5GB
didn't take long to get
Joe Rafaniello
@jrafanie
Feb 02 2016 16:54 UTC
ok, great, thanks
Keenan Brock
@kbrock
Feb 02 2016 16:54 UTC
This message was deleted
Dennis Metzger
@dmetzger57
Feb 02 2016 16:56 UTC
stepping away for 15 minutes
Keenan Brock
@kbrock
Feb 02 2016 16:56 UTC
but what if your db import ends within the next 5 seconds?
Dennis Metzger
@dmetzger57
Feb 02 2016 17:07 UTC
Then it will be waiting for me 😄
Keenan Brock
@kbrock
Feb 02 2016 17:25 UTC
yay
found it
targets.sort { |a,b| target_ids.index(a.id) <=> target_ids.index(b.id) }
Matthew Draper
@matthewd
Feb 02 2016 17:26 UTC
That… seems inefficient
Dennis Metzger
@dmetzger57
Feb 02 2016 17:26 UTC
well then
Matthew Draper
@matthewd
Feb 02 2016 17:27 UTC
x = targets.index_by(&:id); target_ids.map {|id| x[id] } ?
Keenan Brock
@kbrock
Feb 02 2016 17:27 UTC
Rbac.search: 7443.3  +9482.0 
Rbac.sort_targets  5767.0  5767.0  +11154.0
there is other stuff - don't get me wrong
wonder if targets = everything
Matthew Draper
@matthewd
Feb 02 2016 17:28 UTC
target_ids.map(&targets.index_by(&:id)), on 2.3 :sparkles:
Joe Rafaniello
@jrafanie
Feb 02 2016 17:28 UTC
lol, @matthewd Hello, and sorry for the inconvenience, future git-blame users!
I'm from the future ;-)
Keenan Brock
@kbrock
Feb 02 2016 17:29 UTC
why would targets be so big?
why would we have so many ids
anyway
matthew - how sure are you for that solution?
why are we not sorting in the db?
maybe I messed up my refactoring
Matthew Draper
@matthewd
Feb 02 2016 17:30 UTC
Transforms to targets.sort_by {|t| target_ids.index(t.id) }
Keenan Brock
@kbrock
Feb 02 2016 17:30 UTC
I can read that second one
Matthew Draper
@matthewd
Feb 02 2016 17:30 UTC
Getting from there to the map seems fairly straightforward
Keenan Brock
@kbrock
Feb 02 2016 17:31 UTC
is first one better than second?
Matthew Draper
@matthewd
Feb 02 2016 17:31 UTC
Yes
Keenan Brock
@kbrock
Feb 02 2016 17:31 UTC
hmm
Matthew Draper
@matthewd
Feb 02 2016 17:31 UTC
That is: the sort transforms to the sort_by (trivially)
Keenan Brock
@kbrock
Feb 02 2016 17:31 UTC
wonder if we should apply limits before doing the sort
+1
Matthew Draper
@matthewd
Feb 02 2016 17:31 UTC
Then we're sorting the elements in one array, by their (id's) index in another array
That's equivalent to walking the id array, and looking up the corresponding objects (which we do via a hash)
Joe Rafaniello
@jrafanie
Feb 02 2016 17:32 UTC
how many options[:targets] are there?
Matthew Draper
@matthewd
Feb 02 2016 17:33 UTC
(This assumes the arrays are the same size, and each contain no duplicates… but those both seem likely to be true)
.. and you can compact it if you're worried that ids might not have corresponding objects turn up
Jason Frey
@Fryguy
Feb 02 2016 17:33 UTC
targets is probably all the VMs, so like 13k?
there might be some RBAC lookups for the folders as well...not sure
Joe Rafaniello
@jrafanie
Feb 02 2016 17:34 UTC
yay, my database disk wasn't big enough
Dennis Metzger
@dmetzger57
Feb 02 2016 17:34 UTC
been there, blew that up
that's where the TreeBuilderVmsAndTemplates calls into RBAC to prune the data
so, there I would expects vms to be all of them
why are we sorting in RBAC anyway?
Matthew Draper
@matthewd
Feb 02 2016 17:36 UTC
index is O(n), so the current sort is O(n**2 log n) on average
@Fryguy RBAC has to filter the ID list.. then it sorts to get the objects back in the originally provided order
Jason Frey
@Fryguy
Feb 02 2016 17:36 UTC
oh...maybe we can pass an option to say that's not important?
because we don't need it, in this case
Keenan Brock
@kbrock
Feb 02 2016 17:37 UTC
@matthewd
target_ids.map { |id| targets.detect {|t| t.id == id} }
Matthew Draper
@matthewd
Feb 02 2016 17:37 UTC
Just using the hash makes it O(n), so that should be fine
Jason Frey
@Fryguy
Feb 02 2016 17:37 UTC
I mean, we should fix that inefficient sort anyway
but if we can avoid the sort altogether, then it's even better
Keenan Brock
@kbrock
Feb 02 2016 17:37 UTC
typically we filter / order in the db
Matthew Draper
@matthewd
Feb 02 2016 17:37 UTC
@kbrock that's an O(n**2) implementation of the same thing as the index_by
Keenan Brock
@kbrock
Feb 02 2016 17:38 UTC
ok
target_ids.map(&targets.index_by(&:id))
TypeError: wrong argument type Hash (expected Proc)
Jason Frey
@Fryguy
Feb 02 2016 17:38 UTC
^ that's Ruby 2.3 only code
Matthew Draper
@matthewd
Feb 02 2016 17:38 UTC
I did say "if you're on 2.3" :)
You want the one with a temp x
x = targets.index_by(&:id); target_ids.map {|id| x[id] }
^^ that one
Keenan Brock
@kbrock
Feb 02 2016 17:39 UTC
thnx
targets.size == 13k. right?
target_ids = 13k too
aah
but order doesn't matter
we can turn it off for this query
I'll do both
this whole converting into ids.... (tangent sorry)
Matthew Draper
@matthewd
Feb 02 2016 17:41 UTC
I think making it fast should be sufficient, without needing to add extra "skip doing this" logic
Esp if this is for a backport
Keenan Brock
@kbrock
Feb 02 2016 17:41 UTC
if !target_ids.nil? && !options[:order]
you think it would work for :order => id?
Matthew Draper
@matthewd
Feb 02 2016 17:42 UTC
If it's easy, then ¯\_(ツ)_/¯
Jason Frey
@Fryguy
Feb 02 2016 17:42 UTC
if it's sufficiently fast, then yeah, don't worry about the option
Matthew Draper
@matthewd
Feb 02 2016 17:42 UTC
I'd be interested to see comparative timings, anyway
Keenan Brock
@kbrock
Feb 02 2016 17:42 UTC
yea
Jason Frey
@Fryguy
Feb 02 2016 17:43 UTC
I was just throwing the idea out there, particularly if indexing proves to not be a real time saver
Keenan Brock
@kbrock
Feb 02 2016 17:43 UTC
I'm running just the sort
Jason Frey
@Fryguy
Feb 02 2016 17:43 UTC
a sort of 13k objects should not really be expensive
even in Ruby
Keenan Brock
@kbrock
Feb 02 2016 17:43 UTC
"okay?"
7-200ms
49s -> 17s
1 line change
and 99% of the rbac time is now in find_targets_with_direct_rbac
which is where it belongs
EmsVmware#subtree_arranged = next culpret
it is now 2/3 of the time
Oleg Barenboim
@chessbyte
Feb 02 2016 17:46 UTC
@kbrock nice find and teamwork with @matthewd, @Fryguy, @jrafanie and @dmetzger57 -- would not surprise me if I am the author of the offending line of code
Keenan Brock
@kbrock
Feb 02 2016 17:46 UTC
@matthewd that sort was beautiful. and @Fryguy you are right - always sorting is negligible
Matthew Draper
@matthewd
Feb 02 2016 17:47 UTC
Okay, now I'm curious… what's the time with the sort_by version?
Keenan Brock
@kbrock
Feb 02 2016 17:47 UTC
 TreeBuilderVmsAndTemplates#tree  213.8 5151.4  +2289.0 
  TreeBuilderVmsAndTemplates#relationship_tree 467.7 4937.7  +2289.0 
  EmsVmware#subtree_arranged  2987.8  2987.8  +2289.0 
  Rbac.search 10.8  1482.2  +5342.0 
    Rbac.find_targets_with_direct_rbac 1453.4  1453.4  +5358.0
ok
sort_by?
Matthew Draper
@matthewd
Feb 02 2016 17:47 UTC
targets.sort_by {|t| target_ids.index(t.id) }
Keenan Brock
@kbrock
Feb 02 2016 17:47 UTC
sorry
Matthew Draper
@matthewd
Feb 02 2016 17:47 UTC
(clearly much slower.. not suggesting it)
Keenan Brock
@kbrock
Feb 02 2016 17:47 UTC
didn't mean question mark
Oleg Barenboim
@chessbyte
Feb 02 2016 17:48 UTC
@dmetzger57 should we package up this fix and send it to the customer to see if it makes them happier?
Matthew Draper
@matthewd
Feb 02 2016 17:49 UTC
I'm just wondering how much it, as a naïve/literal translation of the sort, improves things on its own
Dennis Metzger
@dmetzger57
Feb 02 2016 17:49 UTC
yea, i’m about to send an update to the email chain suggesting we provide the fix for testing in the customer env
Keenan Brock
@kbrock
Feb 02 2016 17:49 UTC
targets.sort { |a,b| target_ids.index(a.id) <=> target_ids.index(b.id) } # 5 seconds

targets_by_id = targets.index_by(&:id)
target_ids.map {|id| targets_by_id[id] } # 7ms

targets.sort_by {|t| target_ids.index(t.id) } # 19ms
Matthew Draper
@matthewd
Feb 02 2016 17:50 UTC
Woah.. that's better than I expected
(given it's still fundamentally O(n**2))
Keenan Brock
@kbrock
Feb 02 2016 17:52 UTC
in one place, sort_by = 265ms
ok
I have a modified file
and I committed to git (thought I can rollback)
how do I generate a patch (that has filenames and stuff)?
Alex Krzos
@akrzos
Feb 02 2016 17:55 UTC
.patch
Matthew Draper
@matthewd
Feb 02 2016 17:55 UTC
git show ?
Or git diff HEAD^, if you particularly want a less chatty output
(but I'd default to the full commit-as-patch version, personally)
Keenan Brock
@kbrock
Feb 02 2016 17:57 UTC
git diff > rbac_sort.patch
if I git stash
how can I apply - to test?
patch -c . < rbac_sort.patch ?
something like that ? not working
Matthew Draper
@matthewd
Feb 02 2016 17:58 UTC
patch -p1 < thepatch
Keenan Brock
@kbrock
Feb 02 2016 17:59 UTC
thanks
is there a way to get patch to apply absolute directories in the current dir / or diff to generate relative paths?
sweet
thanks
-p2
Joe Rafaniello
@jrafanie
Feb 02 2016 18:11 UTC
yes, @kbrock you can trim the paths using -p
there's also a way to add a prefix
nice find @kbrock
Jason Frey
@Fryguy
Feb 02 2016 18:19 UTC
sort_by is way easier to read for 12ms diff
great work all!
Matthew Draper
@matthewd
Feb 02 2016 18:20 UTC
@Fryguy is it really? :neutral_face:
Jason Frey
@Fryguy
Feb 02 2016 18:20 UTC
I think so, but maybe that's just me
Matthew Draper
@matthewd
Feb 02 2016 18:20 UTC
The index thing took me some re-reading
Jason Frey
@Fryguy
Feb 02 2016 18:20 UTC
ah yeah, ok, I can understand that
Matthew Draper
@matthewd
Feb 02 2016 18:21 UTC
For me, the map more directly implies "an array of the same order"
Jason Frey
@Fryguy
Feb 02 2016 18:21 UTC
but when I see the index, my brain immediately goes to "oh, you're sorting this array by the contents in a different array"
ah ok
so, yeah, let's package this up and try it out :+1:
Matthew Draper
@matthewd
Feb 02 2016 18:22 UTC
Yep.. two sides to the coin :)
Oleg Barenboim
@chessbyte
Feb 02 2016 18:23 UTC
in upstream, my suggestion is to add the faster code - and write a big comment around it
Jason Frey
@Fryguy
Feb 02 2016 18:23 UTC
I don't think it needs a comment either way
it's pretty common to create an index object and then lookup into it to avoid O(n^2)
Matthew Draper
@matthewd
Feb 02 2016 18:24 UTC
Yeah.. I don't think anyone's going to rewrite it to the slow thing, no matter what
(once upon a time, there was no sort_by… and I'm assuming that's when the sort was written)
Jason Frey
@Fryguy
Feb 02 2016 18:25 UTC
as for the "next" thing to do, I noticed that EmsVmware#subtree_arranged was considered the next culprit, so although I'm not against measuring it, I'd be surprised what we can eek out of that...that was already optimized pretty heavily and also starts getting into the ancestry gem, which itself is optimized
the sort_by has been around in our app forever, but for some reason, no one used it early on
I think because either they a) didn't know about it or b) there is a caveat in the documentation that is is "slower"
and so people just avoid it for some reason without measuring
Matthew Draper
@matthewd
Feb 02 2016 18:27 UTC
"slower*"
* if you're sorting a straight array of fixnums
Jason Frey
@Fryguy
Feb 02 2016 18:27 UTC
yes
but that's not what people read...they see slower and then just bail on the idea of using it :/
Matthew Draper
@matthewd
Feb 02 2016 18:28 UTC
See, without people, things would be so much simpler
Jason Frey
@Fryguy
Feb 02 2016 18:28 UTC
hahaha
Alex Krzos
@akrzos
Feb 02 2016 18:38 UTC
@jrafanie @kbrock The same data imported takes 27-22s on 5.5.0.13 vs 68-47s on 5.4.5.0/5.4.4.2
on the same hardware
Thats my "older" hardware
if I move to the newer hardware I bet it's more on the order of 10-15s for 5.5
Dennis Metzger
@dmetzger57
Feb 02 2016 18:40 UTC
@akrzos that’s 5.5.0 with or without @kbrock fix?
Alex Krzos
@akrzos
Feb 02 2016 18:41 UTC
without the fix
Jason Frey
@Fryguy
Feb 02 2016 18:42 UTC
wow...quite the difference
curious how much of the 5.5 timings would be impacted by @kbrock's fix
Joe Rafaniello
@jrafanie
Feb 02 2016 19:03 UTC
@kbrock what are your numbers now with that fix?
Alex Krzos
@akrzos
Feb 02 2016 19:06 UTC
@kbrock could I get the commit and get a few numbers from my appliances?
Dennis Metzger
@dmetzger57
Feb 02 2016 19:07 UTC
@akrzos just forwarded Keenans email with the current patch attached
Keenan Brock
@kbrock
Feb 02 2016 19:21 UTC
sorry
thanks for forwarding @dmetzger57
Dennis Metzger
@dmetzger57
Feb 02 2016 19:21 UTC
n/p
Keenan Brock
@kbrock
Feb 02 2016 19:22 UTC
man I want to refactor rbac :)
Dennis Metzger
@dmetzger57
Feb 02 2016 19:23 UTC
but why ……..
Keenan Brock
@kbrock
Feb 02 2016 19:23 UTC
lol
to be fair, it was already in a list of proposals for you
Dennis Metzger
@dmetzger57
Feb 02 2016 19:23 UTC
yes indeed
Keenan Brock
@kbrock
Feb 02 2016 19:39 UTC
@jrafanie or @Fryguy did you see any improvement? think @dmetzger57 said he saw none
Dennis Metzger
@dmetzger57
Feb 02 2016 19:39 UTC
did not see it running 5.4.1 against Alex’s Large (3,000 VM) env. Trying against the XLarge once it refreshes
Keenan Brock
@kbrock
Feb 02 2016 19:40 UTC
sorry - thanks for the better verbiage
Alex Krzos
@akrzos
Feb 02 2016 19:40 UTC
oh god, 5.4 refresh against xlarge
is lonnnnng
trying the patch now
but witnessed something interesting while getting baseline
5.5 worker recycled
Dennis Metzger
@dmetzger57
Feb 02 2016 19:41 UTC
on the bright side I can make a nice French Press of coffee
Alex Krzos
@akrzos
Feb 02 2016 19:41 UTC
ui worker did
Dennis Metzger
@dmetzger57
Feb 02 2016 19:43 UTC
@akrzos that was with the customer DB, correct?
Alex Krzos
@akrzos
Feb 02 2016 19:44 UTC
yes
I tried to reproduce witha few clicks
and watched mmemory in top on 5.5
and the ui worker grew to around 590MiB RSS
as 5.4 workers were at about 480-490MiB
Dennis Metzger
@dmetzger57
Feb 02 2016 19:44 UTC
Jared is reporting no gain in performance with hi tests of the patch
Alex Krzos
@akrzos
Feb 02 2016 19:44 UTC
but switching to the patch now
Keenan Brock
@kbrock
Feb 02 2016 19:46 UTC
yea - I'm running again locally. I made a lot of modifications, maybe something else is up
testing again
ugh. yea it is quicker locally
I'm going to be ticked if this is the 2nd time I fixed this bug to only find out that my code base was too different from prod
Alex Krzos
@akrzos
Feb 02 2016 19:48 UTC
well patch didn't like 5.5
[root@dhcp23-245 vmdb]# patch < rbac_sort.patch
can't find file to patch at input line 5
Perhaps you should have used the -p or --strip option?
The text leading up to this was:
--------------------------
|diff --git a/vmdb/app/models/rbac.rb b/vmdb/app/models/rbac.rb
|index 8f3fa6d..b583d1e 100644
|--- a/vmdb/app/models/rbac.rb
|+++ b/vmdb/app/models/rbac.rb
--------------------------
File to patch: app/models/rbac.rb
patching file app/models/rbac.rb
Hunk #1 FAILED at 434.
1 out of 1 hunk FAILED -- saving rejects to file app/models/rbac.rb.rej
rebooting my 5.4 machines now and measuring
Keenan Brock
@kbrock
Feb 02 2016 19:49 UTC
@akrzos were 0/2 on that patch :(
ok, reverting that patch (but keeping my other changes locally) - I'm hoping I can at least reproduce locally
Alex Krzos
@akrzos
Feb 02 2016 19:54 UTC
so rebooted with the patch in place
Keenan Brock
@kbrock
Feb 02 2016 19:55 UTC
ok, yes, I show 28 -> 18 the last time
Alex Krzos
@akrzos
Feb 02 2016 19:55 UTC
seeing around a 10s difference with a limited data samples here
Keenan Brock
@kbrock
Feb 02 2016 19:55 UTC
still a lot of time in sorting the table
I'll need to dive into that
darn. only 10s
35%, but was hoping for more
Joe Rafaniello
@jrafanie
Feb 02 2016 20:04 UTC
@kbrock commit the proposed changes locally, git stash all the rest and do your test
still trying to import this enormous database
Keenan Brock
@kbrock
Feb 02 2016 20:04 UTC
heh
just capturing numbers first
Alex Krzos
@akrzos
Feb 02 2016 20:19 UTC
@kbrock so for 5.4 I'm seeing a 17.5-13.4% improvement with your rbac sort patch
Keenan Brock
@kbrock
Feb 02 2016 20:19 UTC
hmm
Alex Krzos
@akrzos
Feb 02 2016 20:19 UTC
that results in in 10-11s at the 99th percentile
bacgtually
99th percentile probably not a good way to summerize this
since the first click is by far the worst
Keenan Brock
@kbrock
Feb 02 2016 20:20 UTC
ooh
Alex Krzos
@akrzos
Feb 02 2016 20:20 UTC
(not cached in any way)
Keenan Brock
@kbrock
Feb 02 2016 20:20 UTC
you can't use the first click
loading rails components unrelated
you could load a different page
Alex Krzos
@akrzos
Feb 02 2016 20:21 UTC
well that screws up with 5.5 because if the worker recycles
it could be any click
Keenan Brock
@kbrock
Feb 02 2016 20:21 UTC
that is why we don't want to do that ;)
Alex Krzos
@akrzos
Feb 02 2016 20:22 UTC
ok got the patch running on 5.5 now
akrzos @akrzos throws away first click on 5.4 to get better %s
Keenan Brock
@kbrock
Feb 02 2016 20:23 UTC
that sounds like we are trying to skew the numbers
lol
Alex Krzos
@akrzos
Feb 02 2016 20:23 UTC
haha
Keenan Brock
@kbrock
Feb 02 2016 20:24 UTC
how about you just pick the biggest pre patch number, and the smallest post patch numbers?
Alex Krzos
@akrzos
Feb 02 2016 20:24 UTC
lol
in that case
can i pick any sample to compare
Keenan Brock
@kbrock
Feb 02 2016 20:24 UTC
no
Alex Krzos
@akrzos
Feb 02 2016 20:24 UTC
jk
Keenan Brock
@kbrock
Feb 02 2016 20:24 UTC
yea
well
I think I did the first hit vs post patch second hit
think that is why my numbers were off
but I just rolled most of my code back and still show 18vs28
Alex Krzos
@akrzos
Feb 02 2016 20:29 UTC
@dmetzger57 You said Jared didn't see any gain with the patch?
Dennis Metzger
@dmetzger57
Feb 02 2016 20:30 UTC
numbers he relayed to me

New Appliance:
28861.4ms
29068.4ms
29235.6ms
30824.7ms

Old Appliance:
29294.0ms
29302.7ms
29559.6ms
29928.8ms
31983.7ms
32099.5ms
34202.0ms

Alex Krzos
@akrzos
Feb 02 2016 20:30 UTC
on the test appliance or in the actual cust environment?
interesting
Dennis Metzger
@dmetzger57
Feb 02 2016 20:31 UTC
Using a 5.4.1 CFME appliance with the customer DB imported
Alex Krzos
@akrzos
Feb 02 2016 20:31 UTC
@kbrock when I look at the cached clicks I see ~23-36% improvement in 99th percentile
basiclly dropping a 50-54s render to a 38-34s
in my env
Keenan Brock
@kbrock
Feb 02 2016 20:33 UTC
nice
Joe Rafaniello
@jrafanie
Feb 02 2016 21:30 UTC
@kbrock what have you been using to profile the code? rubyprof? stackprof?
Keenan Brock
@kbrock
Feb 02 2016 21:30 UTC
mini-rack-profiler
@jrafanie ^
Joe Rafaniello
@jrafanie
Feb 02 2016 21:31 UTC
ok
Keenan Brock
@kbrock
Feb 02 2016 21:31 UTC
ok, so alex and I are seeing this:
Completed 200 OK in 17107.5ms (Views: 567.8ms | ActiveRecord: 1660.3ms)
ooh. I misread that before. I had thought AR =~ total. but it is 10%
Joe Rafaniello
@jrafanie
Feb 02 2016 21:32 UTC
ok, i'll try stackprof, maybe it will show something differently
Keenan Brock
@kbrock
Feb 02 2016 21:32 UTC
great
Dennis Metzger
@dmetzger57
Feb 02 2016 21:33 UTC
@kbrock can you check with Jared, and his appliance, to see what’s up with his 0% improvement
Joe Rafaniello
@jrafanie
Feb 02 2016 21:33 UTC
ugh, using older rubies/bundler/rubygems is so slow
Keenan Brock
@kbrock
Feb 02 2016 21:34 UTC
lol
Joe Rafaniello
@jrafanie
Feb 02 2016 21:34 UTC
"back in my day, ruby 2.0 was fast"
Keenan Brock
@kbrock
Feb 02 2016 21:34 UTC
lol. right?

I created VmShowMixin#feature_tree:
VmInfraController#feature_tree 2,859.6 15,921.6 +447.0

  def feature_tree
    allowed_features = features.select { |f| role_allows(:feature => f.role) }
    allowed_features.each { |feature| build_vm_tree(feature.name, feature.tree_name) }

    trees = allowed_features.map(&:tree_list_name)
    accords = allowed_features.map(&:accord_hash)
    active_elements = allowed_features.first

    [trees, accords, active_elements]
  end

that code is taking 17% of render time

I know that is "small" - but that code doesn't look like it should be so expensive
note, the children take 16k ms (76% of all render time)
Keenan Brock
@kbrock
Feb 02 2016 21:41 UTC
This message was deleted
Matthew Draper
@matthewd
Feb 02 2016 21:42 UTC
children = build_vm_tree ?
Keenan Brock
@kbrock
Feb 02 2016 21:43 UTC
think so
Matthew Draper
@matthewd
Feb 02 2016 21:43 UTC
Are you measuring other children?
Joe Rafaniello
@jrafanie
Feb 02 2016 21:54 UTC
My son is 42 inches tall, he's just big enough to go on roller coasters ;-)
Keenan Brock
@kbrock
Feb 02 2016 21:55 UTC
YAY
Dennis Metzger
@dmetzger57
Feb 02 2016 21:55 UTC
so you can go on coasters together!
Keenan Brock
@kbrock
Feb 02 2016 21:55 UTC
@matthewd fighting on getting my more granular metrics showing up :(
FullTreeBuilder.method_defined?(:convert_to_ui_tree)
it is private
is there a way for me to detect a private method?
Matthew Draper
@matthewd
Feb 02 2016 21:59 UTC
private_method_defined??
Keenan Brock
@kbrock
Feb 02 2016 22:01 UTC
seriously?
cooool
protected too...
@matthewd is there a boolean or something? anykindof_method_defined?(:name)
Matthew Draper
@matthewd
Feb 02 2016 22:02 UTC
I feel like there should be a way to check all at once, but I'm not seeing one
.new.respond_to?(:foo, true) ? :trollface:
Keenan Brock
@kbrock
Feb 02 2016 22:04 UTC
Rack::MiniProfiler.profile_method(klass, method) { |a| name || "#{klass.name}##{method}" }
this fails when method is private :(
Jason Frey
@Fryguy
Feb 02 2016 22:04 UTC
so make it public
(for now)
Keenan Brock
@kbrock
Feb 02 2016 22:04 UTC
mini profiler makes it fail
lol. duh
Fryguy @Fryguy runs away
Matthew Draper
@matthewd
Feb 02 2016 22:05 UTC
I'd monkey-patch profile_method to make it public, even
Keenan Brock
@kbrock
Feb 02 2016 22:05 UTC
+1
@Fryguy that was a duh => me, not you
thanks guys
not sure why it succeeds, but fails silently :(
Matthew Draper
@matthewd
Feb 02 2016 22:06 UTC
There's obviously a super-tiny theoretical chance that making a private method public changes behaviour, but you'll surely notice
Keenan Brock
@kbrock
Feb 02 2016 22:06 UTC
man - so last night around 9PM-11PM I was fighting with this
didn't look at whether something was public / private
Jason Frey
@Fryguy
Feb 02 2016 22:06 UTC
I wrote that code, and I'm 100% sure there's no chance on changing behavior :P
Keenan Brock
@kbrock
Feb 02 2016 22:06 UTC
lol
finally around 1AM I just plain gave up. that 2 hours just threw me
Jason Frey
@Fryguy
Feb 02 2016 22:07 UTC
(assuming you're talking about convert_to_ui_tree)
Oleg Barenboim
@chessbyte
Feb 02 2016 22:07 UTC
@Fryguy why did you and I write most of the slow code?
Keenan Brock
@kbrock
Feb 02 2016 22:07 UTC
it wasn't until 5 seconds ago that I realized the public / private issue
Jason Frey
@Fryguy
Feb 02 2016 22:07 UTC
LOL...believe it or not, that's the FAST code
Keenan Brock
@kbrock
Feb 02 2016 22:07 UTC
@chessbyte FTW
Matthew Draper
@matthewd
Feb 02 2016 22:07 UTC
Jason Frey
@Fryguy
Feb 02 2016 22:07 UTC
the tree walking style was INSANELY slow
Oleg Barenboim
@chessbyte
Feb 02 2016 22:08 UTC
@Fryguy yeah I remember
Keenan Brock
@kbrock
Feb 02 2016 22:08 UTC
@matthewd maybe it is somewhere else
but it just plain stops working
Oleg Barenboim
@chessbyte
Feb 02 2016 22:08 UTC
I STILL do not grok why we need to prepare to show everything and then actually show 1% in the UI
Jason Frey
@Fryguy
Feb 02 2016 22:08 UTC
it was for the twisties and restoring trees
I agree with you...I wish there was a nice way to find a balance
Oleg Barenboim
@chessbyte
Feb 02 2016 22:09 UTC
but that high-level pattern is all over the UI code - including the OpsController where we render each tab (visible or not)
Jason Frey
@Fryguy
Feb 02 2016 22:09 UTC
oddly, the full tree with everything in it, was only a couple seconds slower than the old tree walking style (that is, until you start opening up sections)
Keenan Brock
@kbrock
Feb 02 2016 22:10 UTC
@matthewd here goes nothing
klass.send :public, method
Jason Frey
@Fryguy
Feb 02 2016 22:10 UTC
@chessbyte To your point, and a total aside, I think there are huge gains to be made by doing simple things like not rendering hidden stuff...accordions, tabs, etc
Keenan Brock
@kbrock
Feb 02 2016 22:10 UTC
I want an option that doesn't send archived or orphans
make them into a view/filter rather than a wingding
few BZs talking about performance issues
Matthew Draper
@matthewd
Feb 02 2016 22:11 UTC
If archived and orphans get sent, why do I get a spinner when I expand them? :confused:
Keenan Brock
@kbrock
Feb 02 2016 22:11 UTC
ooh
darn
Jason Frey
@Fryguy
Feb 02 2016 22:11 UTC
because they are not FullTreeBuilder based
Keenan Brock
@kbrock
Feb 02 2016 22:11 UTC
@Fryguy translate?
Jason Frey
@Fryguy
Feb 02 2016 22:11 UTC
this might be a lot easier on a BlueJeans :P
Keenan Brock
@kbrock
Feb 02 2016 22:12 UTC
did you just say "keenan - no, we do not send them down until they are expanded" ?
Jason Frey
@Fryguy
Feb 02 2016 22:12 UTC
correct
Keenan Brock
@kbrock
Feb 02 2016 22:12 UTC
thanks
but
but
that is one of my rants
awh man
complainers gonna complain complain complain
Oleg Barenboim
@chessbyte
Feb 02 2016 22:12 UTC
@kbrock - don't rant, just fix
Keenan Brock
@kbrock
Feb 02 2016 22:13 UTC
as long as it is on topic ;)
Jason Frey
@Fryguy
Feb 02 2016 22:13 UTC
what @chessbyte and I were referring to (for the general performance team @dmetzger57) was even simpler...
when there are multiple accordions or tabs...each of the contents of those are fully rendered when they don't need to be
e.g. when you go to Configuration screen, it renders the Database Diagnostics accordion, even if no one ever clicks it
Keenan Brock
@kbrock
Feb 02 2016 22:14 UTC
ok - vs sent down
Jason Frey
@Fryguy
Feb 02 2016 22:14 UTC
you can see TONS of queries to build all that crap up
(P.S. this particular example is the reason why we need to seed VmdbDatabase and friends primordially)
but that's an aside for prioritzation by @dmetzger57 :D
Keenan Brock
@kbrock
Feb 02 2016 22:17 UTC
well, today I couldn't afford to run primordial seeds
restarting the appliance 100+ times w/ an extra ~1/2 minute each...
sorry / ignore
Jason Frey
@Fryguy
Feb 02 2016 22:20 UTC
back on topic...there are 2 kinds of TreeBuilders...walking-style and full. The only instance of a FullTreeBuilder is the TreeBuildVmsAndTemplates. It was written to solve https://bugzilla.redhat.com/show_bug.cgi?id=1086015
Keenan Brock
@kbrock
Feb 02 2016 22:20 UTC
yup
Jason Frey
@Fryguy
Feb 02 2016 22:21 UTC
More information, if it's useful: ManageIQ/manageiq#131
Keenan Brock
@kbrock
Feb 02 2016 22:21 UTC
thanks
the way rbac is used there is tricky
wonder if it is possible to run that 1 time for 6 ems trees rather than 1 / ems (6 times).
Jason Frey
@Fryguy
Feb 02 2016 22:23 UTC
the walker-style TreeBuilders are interesting, because they are really fast in the base case...they only load what you can see in the UI, and load the next parts on demand
the down side is that tree state is saved in the session, so if you leave and come back (or just refresh the whole page), it is equivalent in performance to clicking the twisty on every single item
Keenan Brock
@kbrock
Feb 02 2016 22:24 UTC
clicking sort / changing the view
Jason Frey
@Fryguy
Feb 02 2016 22:24 UTC
basically, it becomes this RIDICULOUS N+1
Keenan Brock
@kbrock
Feb 02 2016 22:24 UTC
the right hand side is only a few second
Jason Frey
@Fryguy
Feb 02 2016 22:24 UTC
no, opening up the nodes on the tree
Keenan Brock
@kbrock
Feb 02 2016 22:24 UTC
but with the left hand side (nothing expanded) the thing takes much longer
Jason Frey
@Fryguy
Feb 02 2016 22:25 UTC
when i said "the tree state is saved", I meant the "open/closed node states of the tree are saved"
Keenan Brock
@kbrock
Feb 02 2016 22:25 UTC
yea, I think I know the code
at least for features and expanding trees
Jason Frey
@Fryguy
Feb 02 2016 22:25 UTC
yes, the base case (nothing expanded) is technically slower, but I felt the tradeoff was ok
usually something always ends up opened...like if you come from the EMS page and click on VMs, the UI will automatically open the tree nodes to the right place
Keenan Brock
@kbrock
Feb 02 2016 22:26 UTC
@matthewd ideas why this doesn't fix the profiling_methods.rb of a private method?
klass.send :public, method
getting no errors, rack-mini-profiler simply stops working
@Fryguy just deleting the 'private' word does fix it
Jason Frey
@Fryguy
Feb 02 2016 22:28 UTC
yeah, I was suggesting just removing "private" in the code...for now
Keenan Brock
@kbrock
Feb 02 2016 22:28 UTC
yup
Jason Frey
@Fryguy
Feb 02 2016 22:28 UTC
(btw, this was a cool trip down memory lane...I spent ages on that BZ :grin:)
Keenan Brock
@kbrock
Feb 02 2016 22:28 UTC
was hoping to fix it so I didn't have to go through all the classes and remember this
yay
"good times" FTW
Jason Frey
@Fryguy
Feb 02 2016 22:29 UTC
@chessbyte I think that was around when I did the first xnode refactoring
Joe Rafaniello
@jrafanie
Feb 02 2016 22:29 UTC
I have rubyprof working on a per rack request... I got it with the initial vm_infra/explorer... would anyone want ot take a look? I'll upload it somewhere if so
Jason Frey
@Fryguy
Feb 02 2016 22:29 UTC
because the UI there was some damn complicated, and I needed common methods to make it usable
Matthew Draper
@matthewd
Feb 02 2016 22:29 UTC
Probably related to my confusion that it's breaking in the first place.. but no, no specific ideas
Joe Rafaniello
@jrafanie
Feb 02 2016 23:04 UTC
with ruby-prof, even on the second visit to vm_infra/explorer i'm seeing we're spending nearly 20% of our time in Ancestry::ClassMethods#arrange_nodes
Screen Shot 2016-02-02 at 6.00.12 PM.png
Keenan Brock
@kbrock
Feb 02 2016 23:05 UTC
@jrafanie I'm seeing some stuff in there too
I had looked at the gem
we have commit access to it now
@matthewd found the problem - it is a recursive function - was generating too much data
not public / private at all!
Joe Rafaniello
@jrafanie
Feb 02 2016 23:07 UTC
so, rubyprof is reporting it wrong?
Keenan Brock
@kbrock
Feb 02 2016 23:08 UTC
@jrafanie sorry - different problem
my profiler was messing up when profiling recursive functions
Joe Rafaniello
@jrafanie
Feb 02 2016 23:08 UTC
ok
Keenan Brock
@kbrock
Feb 02 2016 23:08 UTC
@jrafanie yes - I think there is something wrong in there
Joe Rafaniello
@jrafanie
Feb 02 2016 23:08 UTC
So, we're also instantiating the same vms twice
Keenan Brock
@kbrock
Feb 02 2016 23:08 UTC
yes
first page rendering:
Rendering: layouts/exp_atom/_editor 2871.2 2871.2
Joe Rafaniello
@jrafanie
Feb 02 2016 23:09 UTC
and the default_value_for set defaults on initialize is not fast when you run it tens of thousands of times
Keenan Brock
@kbrock
Feb 02 2016 23:09 UTC
second one makes it small. but since I'm doing first / second render so often... very noticable for me
@jrafanie yes
Joe Rafaniello
@jrafanie
Feb 02 2016 23:09 UTC
not more than 5 % though, so probably not a big deal
Keenan Brock
@kbrock
Feb 02 2016 23:09 UTC
heh
... just use the database defaults like most rails apps...
may be a thought
@jrafanie you looking at EmsVmware#subtree_arranged ?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:11 UTC
I'm looking at the whole thing in rubyprof
Keenan Brock
@kbrock
Feb 02 2016 23:11 UTC
what is your script?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:11 UTC
config.middleware.use Rack::RubyProf, :path => '/Users/joerafaniello/Code/manageiq/vmdb/tmp/profile' in config/application.rb
Keenan Brock
@kbrock
Feb 02 2016 23:11 UTC
ooh - cool
Joe Rafaniello
@jrafanie
Feb 02 2016 23:12 UTC
change for your path
it dumps a few htmls on each request
it's slow though
Keenan Brock
@kbrock
Feb 02 2016 23:13 UTC
I couldn't get ruby-prof to load. I disabled it locally
you running ruby 2.0.0?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:13 UTC
I went with 2.1
Keenan Brock
@kbrock
Feb 02 2016 23:13 UTC
k
then it runs?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:13 UTC
reproduced slowness on the same page with 2.1 so I tried with rubyprof
VmOrTemplate#normalized_state burns my soul
we call it in the hamls 10k times
sends a bunch of methods which calls associations
Keenan Brock
@kbrock
Feb 02 2016 23:14 UTC
yea - not a fan of associations :(
Joe Rafaniello
@jrafanie
Feb 02 2016 23:14 UTC
but again, not much more than 3 % of the total time
Keenan Brock
@kbrock
Feb 02 2016 23:14 UTC
I'll have to peek in there
may be 3%, but it still burns the soul
ok, need to duck out for a bit.
catch you all later
Joe Rafaniello
@jrafanie
Feb 02 2016 23:20 UTC
Good night
Dennis Metzger
@dmetzger57
Feb 02 2016 23:21 UTC
‘night @jrafanie