These are chat archives for ManageIQ/manageiq/performance

2nd
Feb 2016
Keenan Brock
@kbrock
Feb 02 2016 13:52
@dmetzger57 you having fun yet?
Dennis Metzger
@dmetzger57
Feb 02 2016 13:53
that’s one description
Keenan Brock
@kbrock
Feb 02 2016 13:53
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
so you’ve identified where we spend large chunks of time
Keenan Brock
@kbrock
Feb 02 2016 13:54
yes
Dennis Metzger
@dmetzger57
Feb 02 2016 13:54
i just run against 10.10.182.120 and was about to do that
Keenan Brock
@kbrock
Feb 02 2016 13:55
I have the db local
Dennis Metzger
@dmetzger57
Feb 02 2016 13:55
looking at evm.log and production.log
Keenan Brock
@kbrock
Feb 02 2016 13:55
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
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
it is dispersed :(
total = 27k
explorer = 26k
feature tree = 25.6k
(I'm diving down)
Dennis Metzger
@dmetzger57
Feb 02 2016 13:58
whats the unit of measure there “27k"
Matthew Draper
@matthewd
Feb 02 2016 13:58
k = thousands of ms?
Keenan Brock
@kbrock
Feb 02 2016 13:58
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
Do you have 6 EMSes?
Keenan Brock
@kbrock
Feb 02 2016 14:01
sorry -in the future I'll be able to post text
1
hmm
Jason Frey
@Fryguy
Feb 02 2016 14:02
Interesting... There are multiple trees per accordion
Dennis Metzger
@dmetzger57
Feb 02 2016 14:02
yea they have 6 providers
Jason Frey
@Fryguy
Feb 02 2016 14:03
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
image
Jason Frey
@Fryguy
Feb 02 2016 14:03
You could probably save a TON of time by not having it do that
Keenan Brock
@kbrock
Feb 02 2016 14:04
bringing back every record does hit us
Jason Frey
@Fryguy
Feb 02 2016 14:04
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
13k vm, 700 archived, 149 orphaned
Matthew Draper
@matthewd
Feb 02 2016 14:04
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
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
@matthewd rubygems tried master, 0.9.8, 0.1.31
Jason Frey
@Fryguy
Feb 02 2016 14:07
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
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
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
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
I had that much on my original code... It wasn't that bad
Keenan Brock
@kbrock
Feb 02 2016 14:08
ALSO
sorting in ruby is taking some time
Jason Frey
@Fryguy
Feb 02 2016 14:08
Something new must be in the way
Matthew Draper
@matthewd
Feb 02 2016 14:09
@kbrock do you just need to backport @Fryguy's changes from master? Is that feasible?
Keenan Brock
@kbrock
Feb 02 2016 14:09
those changes are in there
Jason Frey
@Fryguy
Feb 02 2016 14:09
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
@Fryguy so, the right hand side is taking 500ms
Matthew Draper
@matthewd
Feb 02 2016 14:10
But master is fine? :confused:
Keenan Brock
@kbrock
Feb 02 2016 14:10
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
master has a different problem (the icon thing)
Jason Frey
@Fryguy
Feb 02 2016 14:10
Ahhhhh... D
Keenan Brock
@kbrock
Feb 02 2016 14:10
we are downloading everything
ooh
yes
icon = 75% of problem (4 different icons ;) )
Jason Frey
@Fryguy
Feb 02 2016 14:10
Archived is not one of those full trees
Matthew Draper
@matthewd
Feb 02 2016 14:10
Apart from the icons, master is fine?
Jason Frey
@Fryguy
Feb 02 2016 14:10
Nor is orphaned
Keenan Brock
@kbrock
Feb 02 2016 14:10
we download ALL of both from the db
all columns of those
Jason Frey
@Fryguy
Feb 02 2016 14:11
I never got around to updating those trees
Keenan Brock
@kbrock
Feb 02 2016 14:11
anyway
not the problem today
Jason Frey
@Fryguy
Feb 02 2016 14:11
Oh wait... Are you saying archived and orphaned are not the problem? I'm confused
Keenan Brock
@kbrock
Feb 02 2016 14:11
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
On master, when you skipped the icons, the performance was fine.. wasn't it?
Keenan Brock
@kbrock
Feb 02 2016 14:12
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
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
Compared to 30s, 4s sounds like "fine" to me
Alex Krzos
@akrzos
Feb 02 2016 14:13
@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
I guess
Matthew Draper
@matthewd
Feb 02 2016 14:13
Solve one problem at a time
Jason Frey
@Fryguy
Feb 02 2016 14:13
@akrzos I tested locally with 10000 ;)
Alex Krzos
@akrzos
Feb 02 2016 14:13
It has always been a problem when there was 10000
Matthew Draper
@matthewd
Feb 02 2016 14:14
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
Oh really? That's news to me :(
Matthew Draper
@matthewd
Feb 02 2016 14:15
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
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
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
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
1/3 = arrange, 1/2 = rbac finding targets (which they are already local :( )
Matthew Draper
@matthewd
Feb 02 2016 14:20
What makes master so much better there?
Keenan Brock
@kbrock
Feb 02 2016 14:20
@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
But.. you said master was 4s
Keenan Brock
@kbrock
Feb 02 2016 14:21
sorry - determine_ids_clause = me dividing up rbac trying to find problems
Matthew Draper
@matthewd
Feb 02 2016 14:21
There's a single method call that's 6s right there
Keenan Brock
@kbrock
Feb 02 2016 14:21
@matthewd sorry - forgot headers
Matthew Draper
@matthewd
Feb 02 2016 14:22
I know what the columns are
Keenan Brock
@kbrock
Feb 02 2016 14:22
aah - yes, 3s + 7.5s
Matthew Draper
@matthewd
Feb 02 2016 14:22
Is master 4s, or not?
Keenan Brock
@kbrock
Feb 02 2016 14:22
dunno
Matthew Draper
@matthewd
Feb 02 2016 14:23
non-icons was 4 seconds (vs 14 seconds) - master
Keenan Brock
@kbrock
Feb 02 2016 14:23
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
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
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
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
is it all vmware?
Keenan Brock
@kbrock
Feb 02 2016 14:34
great question => yes all vmware
Joe Rafaniello
@jrafanie
Feb 02 2016 14:34
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
local database on my machine- exact copy
different version of postgres
Joe Rafaniello
@jrafanie
Feb 02 2016 14:36
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
customer version == 5.4.1.0
Joe Rafaniello
@jrafanie
Feb 02 2016 14:37
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
ooh - yes. I'm on 5.4.z
Joe Rafaniello
@jrafanie
Feb 02 2016 14:37
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
getting numbers for 5.4.z
Joe Rafaniello
@jrafanie
Feb 02 2016 14:38
ok
thanks!
Keenan Brock
@kbrock
Feb 02 2016 14:38
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
So, production mode then...
Keenan Brock
@kbrock
Feb 02 2016 14:39
... hold please... :(
Joe Rafaniello
@jrafanie
Feb 02 2016 14:39
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
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
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
  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
@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
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
@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
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
excellent bookmarked for the future
Keenan Brock
@kbrock
Feb 02 2016 15:00
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
lol
Alex Krzos
@akrzos
Feb 02 2016 15:03
5.4 to 5.5 is a different underlying os
rhel 6 to rhel 7
Dennis Metzger
@dmetzger57
Feb 02 2016 15:03
yea, the number of variables is most impressive
Keenan Brock
@kbrock
Feb 02 2016 15:04
#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
Yes @kbrock that's a pain I hate
Keenan Brock
@kbrock
Feb 02 2016 15:11
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
primordial includes VmdbDatabase.seed which is not primordial
Keenan Brock
@kbrock
Feb 02 2016 15:11
heh
Joe Rafaniello
@jrafanie
Feb 02 2016 15:11
but alas, the UI can't run without it
Keenan Brock
@kbrock
Feb 02 2016 15:12
well, nothing can run without seeds
anyway
sorry
tangent
"tomorrow"
Joe Rafaniello
@jrafanie
Feb 02 2016 15:12
:squirrel:
squirrel ;-)
Dennis Metzger
@dmetzger57
Feb 02 2016 15:12
squirrel chasing ….
Joe Rafaniello
@jrafanie
Feb 02 2016 15:12
:sparkle:
Keenan Brock
@kbrock
Feb 02 2016 15:12
;)
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
fyi:
Completed 200 OK in 23239.6ms (Views: 152.7ms | ActiveRecord: 1003.9ms)
Oleg Barenboim
@chessbyte
Feb 02 2016 16:15
23 seconds? wow
Keenan Brock
@kbrock
Feb 02 2016 16:15
and not an N+1
Oleg Barenboim
@chessbyte
Feb 02 2016 16:18
@kbrock - please tell me that is before any performance improvements ;-)
Keenan Brock
@kbrock
Feb 02 2016 16:18
+1
BEFORE
50% in rbac
think it is in object invocation, still trying to track down
Joe Rafaniello
@jrafanie
Feb 02 2016 16:35
@kbrock context? 23 seconds... what scenario? master/5.5/5.4? What # of vms?
Keenan Brock
@kbrock
Feb 02 2016 16:36
@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
@jrafanie would appreciate your help here as customer is escalating this issue
Keenan Brock
@kbrock
Feb 02 2016 16:37
@chessbyte @jrafanie has been hooking us up
Joe Rafaniello
@jrafanie
Feb 02 2016 16:37
Sure, how can I help?
Oleg Barenboim
@chessbyte
Feb 02 2016 16:39
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
ok, @dmetzger57 please DM me where I can get the DB
Dennis Metzger
@dmetzger57
Feb 02 2016 16:41
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
+1
Dennis Metzger
@dmetzger57
Feb 02 2016 16:43
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
(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
+1
Joe Rafaniello
@jrafanie
Feb 02 2016 16:45
thanks
Dennis Metzger
@dmetzger57
Feb 02 2016 16:45
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
@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
Great, thanks.... so, have we confirmed master is exhibiting the same slowdown in the same area?
Dennis Metzger
@dmetzger57
Feb 02 2016 16:47
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
ok
Dennis Metzger
@dmetzger57
Feb 02 2016 16:48
the import takes a while
at least in my environment
Keenan Brock
@kbrock
Feb 02 2016 16:48
heh - a long while
Joe Rafaniello
@jrafanie
Feb 02 2016 16:48
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
i have not
Keenan Brock
@kbrock
Feb 02 2016 16:49
no way - I waited 1/2 an hour to get them into my db ;)
Joe Rafaniello
@jrafanie
Feb 02 2016 16:49
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
each time?
aah - change being changing the manageiq version not the code
Dennis Metzger
@dmetzger57
Feb 02 2016 16:52
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
is the dump less than 10 GB?
Keenan Brock
@kbrock
Feb 02 2016 16:54
yes
dump is 1.5GB
didn't take long to get
Joe Rafaniello
@jrafanie
Feb 02 2016 16:54
ok, great, thanks
Keenan Brock
@kbrock
Feb 02 2016 16:54
This message was deleted
Dennis Metzger
@dmetzger57
Feb 02 2016 16:56
stepping away for 15 minutes
Keenan Brock
@kbrock
Feb 02 2016 16:56
but what if your db import ends within the next 5 seconds?
Dennis Metzger
@dmetzger57
Feb 02 2016 17:07
Then it will be waiting for me 😄
Keenan Brock
@kbrock
Feb 02 2016 17:25
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
That… seems inefficient
Dennis Metzger
@dmetzger57
Feb 02 2016 17:26
well then
Matthew Draper
@matthewd
Feb 02 2016 17:27
x = targets.index_by(&:id); target_ids.map {|id| x[id] } ?
Keenan Brock
@kbrock
Feb 02 2016 17:27
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
target_ids.map(&targets.index_by(&:id)), on 2.3 :sparkles:
Joe Rafaniello
@jrafanie
Feb 02 2016 17:28
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
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
Transforms to targets.sort_by {|t| target_ids.index(t.id) }
Keenan Brock
@kbrock
Feb 02 2016 17:30
I can read that second one
Matthew Draper
@matthewd
Feb 02 2016 17:30
Getting from there to the map seems fairly straightforward
Keenan Brock
@kbrock
Feb 02 2016 17:31
is first one better than second?
Matthew Draper
@matthewd
Feb 02 2016 17:31
Yes
Keenan Brock
@kbrock
Feb 02 2016 17:31
hmm
Matthew Draper
@matthewd
Feb 02 2016 17:31
That is: the sort transforms to the sort_by (trivially)
Keenan Brock
@kbrock
Feb 02 2016 17:31
wonder if we should apply limits before doing the sort
+1
Matthew Draper
@matthewd
Feb 02 2016 17:31
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
how many options[:targets] are there?
Matthew Draper
@matthewd
Feb 02 2016 17:33
(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
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
yay, my database disk wasn't big enough
Dennis Metzger
@dmetzger57
Feb 02 2016 17:34
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
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
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
@matthewd
target_ids.map { |id| targets.detect {|t| t.id == id} }
Matthew Draper
@matthewd
Feb 02 2016 17:37
Just using the hash makes it O(n), so that should be fine
Jason Frey
@Fryguy
Feb 02 2016 17:37
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
typically we filter / order in the db
Matthew Draper
@matthewd
Feb 02 2016 17:37
@kbrock that's an O(n**2) implementation of the same thing as the index_by
Keenan Brock
@kbrock
Feb 02 2016 17:38
ok
target_ids.map(&targets.index_by(&:id))
TypeError: wrong argument type Hash (expected Proc)
Jason Frey
@Fryguy
Feb 02 2016 17:38
^ that's Ruby 2.3 only code
Matthew Draper
@matthewd
Feb 02 2016 17:38
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
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
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
if !target_ids.nil? && !options[:order]
you think it would work for :order => id?
Matthew Draper
@matthewd
Feb 02 2016 17:42
If it's easy, then ¯\_(ツ)_/¯
Jason Frey
@Fryguy
Feb 02 2016 17:42
if it's sufficiently fast, then yeah, don't worry about the option
Matthew Draper
@matthewd
Feb 02 2016 17:42
I'd be interested to see comparative timings, anyway
Keenan Brock
@kbrock
Feb 02 2016 17:42
yea
Jason Frey
@Fryguy
Feb 02 2016 17:43
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
I'm running just the sort
Jason Frey
@Fryguy
Feb 02 2016 17:43
a sort of 13k objects should not really be expensive
even in Ruby
Keenan Brock
@kbrock
Feb 02 2016 17:43
"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
@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
@matthewd that sort was beautiful. and @Fryguy you are right - always sorting is negligible
Matthew Draper
@matthewd
Feb 02 2016 17:47
Okay, now I'm curious… what's the time with the sort_by version?
Keenan Brock
@kbrock
Feb 02 2016 17:47
 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
targets.sort_by {|t| target_ids.index(t.id) }
Keenan Brock
@kbrock
Feb 02 2016 17:47
sorry
Matthew Draper
@matthewd
Feb 02 2016 17:47
(clearly much slower.. not suggesting it)
Keenan Brock
@kbrock
Feb 02 2016 17:47
didn't mean question mark
Oleg Barenboim
@chessbyte
Feb 02 2016 17:48
@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
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
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
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
Woah.. that's better than I expected
(given it's still fundamentally O(n**2))
Keenan Brock
@kbrock
Feb 02 2016 17:52
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
.patch
Matthew Draper
@matthewd
Feb 02 2016 17:55
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
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
patch -p1 < thepatch
Keenan Brock
@kbrock
Feb 02 2016 17:59
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
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
sort_by is way easier to read for 12ms diff
great work all!
Matthew Draper
@matthewd
Feb 02 2016 18:20
@Fryguy is it really? :neutral_face:
Jason Frey
@Fryguy
Feb 02 2016 18:20
I think so, but maybe that's just me
Matthew Draper
@matthewd
Feb 02 2016 18:20
The index thing took me some re-reading
Jason Frey
@Fryguy
Feb 02 2016 18:20
ah yeah, ok, I can understand that
Matthew Draper
@matthewd
Feb 02 2016 18:21
For me, the map more directly implies "an array of the same order"
Jason Frey
@Fryguy
Feb 02 2016 18:21
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
Yep.. two sides to the coin :)
Oleg Barenboim
@chessbyte
Feb 02 2016 18:23
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
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
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
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
"slower*"
* if you're sorting a straight array of fixnums
Jason Frey
@Fryguy
Feb 02 2016 18:27
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
See, without people, things would be so much simpler
Jason Frey
@Fryguy
Feb 02 2016 18:28
hahaha
Alex Krzos
@akrzos
Feb 02 2016 18:38
@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
@akrzos that’s 5.5.0 with or without @kbrock fix?
Alex Krzos
@akrzos
Feb 02 2016 18:41
without the fix
Jason Frey
@Fryguy
Feb 02 2016 18:42
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
@kbrock what are your numbers now with that fix?
Alex Krzos
@akrzos
Feb 02 2016 19:06
@kbrock could I get the commit and get a few numbers from my appliances?
Dennis Metzger
@dmetzger57
Feb 02 2016 19:07
@akrzos just forwarded Keenans email with the current patch attached
Keenan Brock
@kbrock
Feb 02 2016 19:21
sorry
thanks for forwarding @dmetzger57
Dennis Metzger
@dmetzger57
Feb 02 2016 19:21
n/p
Keenan Brock
@kbrock
Feb 02 2016 19:22
man I want to refactor rbac :)
Dennis Metzger
@dmetzger57
Feb 02 2016 19:23
but why ……..
Keenan Brock
@kbrock
Feb 02 2016 19:23
lol
to be fair, it was already in a list of proposals for you
Dennis Metzger
@dmetzger57
Feb 02 2016 19:23
yes indeed
Keenan Brock
@kbrock
Feb 02 2016 19:39
@jrafanie or @Fryguy did you see any improvement? think @dmetzger57 said he saw none
Dennis Metzger
@dmetzger57
Feb 02 2016 19:39
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
sorry - thanks for the better verbiage
Alex Krzos
@akrzos
Feb 02 2016 19:40
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
on the bright side I can make a nice French Press of coffee
Alex Krzos
@akrzos
Feb 02 2016 19:41
ui worker did
Dennis Metzger
@dmetzger57
Feb 02 2016 19:43
@akrzos that was with the customer DB, correct?
Alex Krzos
@akrzos
Feb 02 2016 19:44
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
Jared is reporting no gain in performance with hi tests of the patch
Alex Krzos
@akrzos
Feb 02 2016 19:44
but switching to the patch now
Keenan Brock
@kbrock
Feb 02 2016 19:46
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
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
@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
so rebooted with the patch in place
Keenan Brock
@kbrock
Feb 02 2016 19:55
ok, yes, I show 28 -> 18 the last time
Alex Krzos
@akrzos
Feb 02 2016 19:55
seeing around a 10s difference with a limited data samples here
Keenan Brock
@kbrock
Feb 02 2016 19:55
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
@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
heh
just capturing numbers first
Alex Krzos
@akrzos
Feb 02 2016 20:19
@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
hmm
Alex Krzos
@akrzos
Feb 02 2016 20:19
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
ooh
Alex Krzos
@akrzos
Feb 02 2016 20:20
(not cached in any way)
Keenan Brock
@kbrock
Feb 02 2016 20:20
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
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
that is why we don't want to do that ;)
Alex Krzos
@akrzos
Feb 02 2016 20:22
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
that sounds like we are trying to skew the numbers
lol
Alex Krzos
@akrzos
Feb 02 2016 20:23
haha
Keenan Brock
@kbrock
Feb 02 2016 20:24
how about you just pick the biggest pre patch number, and the smallest post patch numbers?
Alex Krzos
@akrzos
Feb 02 2016 20:24
lol
in that case
can i pick any sample to compare
Keenan Brock
@kbrock
Feb 02 2016 20:24
no
Alex Krzos
@akrzos
Feb 02 2016 20:24
jk
Keenan Brock
@kbrock
Feb 02 2016 20:24
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
@dmetzger57 You said Jared didn't see any gain with the patch?
Dennis Metzger
@dmetzger57
Feb 02 2016 20:30
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
on the test appliance or in the actual cust environment?
interesting
Dennis Metzger
@dmetzger57
Feb 02 2016 20:31
Using a 5.4.1 CFME appliance with the customer DB imported
Alex Krzos
@akrzos
Feb 02 2016 20:31
@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
nice
Joe Rafaniello
@jrafanie
Feb 02 2016 21:30
@kbrock what have you been using to profile the code? rubyprof? stackprof?
Keenan Brock
@kbrock
Feb 02 2016 21:30
mini-rack-profiler
@jrafanie ^
Joe Rafaniello
@jrafanie
Feb 02 2016 21:31
ok
Keenan Brock
@kbrock
Feb 02 2016 21:31
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
ok, i'll try stackprof, maybe it will show something differently
Keenan Brock
@kbrock
Feb 02 2016 21:32
great
Dennis Metzger
@dmetzger57
Feb 02 2016 21:33
@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
ugh, using older rubies/bundler/rubygems is so slow
Keenan Brock
@kbrock
Feb 02 2016 21:34
lol
Joe Rafaniello
@jrafanie
Feb 02 2016 21:34
"back in my day, ruby 2.0 was fast"
Keenan Brock
@kbrock
Feb 02 2016 21:34
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
This message was deleted
Matthew Draper
@matthewd
Feb 02 2016 21:42
children = build_vm_tree ?
Keenan Brock
@kbrock
Feb 02 2016 21:43
think so
Matthew Draper
@matthewd
Feb 02 2016 21:43
Are you measuring other children?
Joe Rafaniello
@jrafanie
Feb 02 2016 21:54
My son is 42 inches tall, he's just big enough to go on roller coasters ;-)
Keenan Brock
@kbrock
Feb 02 2016 21:55
YAY
Dennis Metzger
@dmetzger57
Feb 02 2016 21:55
so you can go on coasters together!
Keenan Brock
@kbrock
Feb 02 2016 21:55
@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
private_method_defined??
Keenan Brock
@kbrock
Feb 02 2016 22:01
seriously?
cooool
protected too...
@matthewd is there a boolean or something? anykindof_method_defined?(:name)
Matthew Draper
@matthewd
Feb 02 2016 22:02
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
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
so make it public
(for now)
Keenan Brock
@kbrock
Feb 02 2016 22:04
mini profiler makes it fail
lol. duh
Fryguy @Fryguy runs away
Matthew Draper
@matthewd
Feb 02 2016 22:05
I'd monkey-patch profile_method to make it public, even
Keenan Brock
@kbrock
Feb 02 2016 22:05
+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
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
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
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
lol
finally around 1AM I just plain gave up. that 2 hours just threw me
Jason Frey
@Fryguy
Feb 02 2016 22:07
(assuming you're talking about convert_to_ui_tree)
Oleg Barenboim
@chessbyte
Feb 02 2016 22:07
@Fryguy why did you and I write most of the slow code?
Keenan Brock
@kbrock
Feb 02 2016 22:07
it wasn't until 5 seconds ago that I realized the public / private issue
Jason Frey
@Fryguy
Feb 02 2016 22:07
LOL...believe it or not, that's the FAST code
Keenan Brock
@kbrock
Feb 02 2016 22:07
@chessbyte FTW
Matthew Draper
@matthewd
Feb 02 2016 22:07
Jason Frey
@Fryguy
Feb 02 2016 22:07
the tree walking style was INSANELY slow
Oleg Barenboim
@chessbyte
Feb 02 2016 22:08
@Fryguy yeah I remember
Keenan Brock
@kbrock
Feb 02 2016 22:08
@matthewd maybe it is somewhere else
but it just plain stops working
Oleg Barenboim
@chessbyte
Feb 02 2016 22:08
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
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
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
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
@matthewd here goes nothing
klass.send :public, method
Jason Frey
@Fryguy
Feb 02 2016 22:10
@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
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
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
ooh
darn
Jason Frey
@Fryguy
Feb 02 2016 22:11
because they are not FullTreeBuilder based
Keenan Brock
@kbrock
Feb 02 2016 22:11
@Fryguy translate?
Jason Frey
@Fryguy
Feb 02 2016 22:11
this might be a lot easier on a BlueJeans :P
Keenan Brock
@kbrock
Feb 02 2016 22:12
did you just say "keenan - no, we do not send them down until they are expanded" ?
Jason Frey
@Fryguy
Feb 02 2016 22:12
correct
Keenan Brock
@kbrock
Feb 02 2016 22:12
thanks
but
but
that is one of my rants
awh man
complainers gonna complain complain complain
Oleg Barenboim
@chessbyte
Feb 02 2016 22:12
@kbrock - don't rant, just fix
Keenan Brock
@kbrock
Feb 02 2016 22:13
as long as it is on topic ;)
Jason Frey
@Fryguy
Feb 02 2016 22:13
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
ok - vs sent down
Jason Frey
@Fryguy
Feb 02 2016 22:14
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
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
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
yup
Jason Frey
@Fryguy
Feb 02 2016 22:21
More information, if it's useful: ManageIQ/manageiq#131
Keenan Brock
@kbrock
Feb 02 2016 22:21
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
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
clicking sort / changing the view
Jason Frey
@Fryguy
Feb 02 2016 22:24
basically, it becomes this RIDICULOUS N+1
Keenan Brock
@kbrock
Feb 02 2016 22:24
the right hand side is only a few second
Jason Frey
@Fryguy
Feb 02 2016 22:24
no, opening up the nodes on the tree
Keenan Brock
@kbrock
Feb 02 2016 22:24
but with the left hand side (nothing expanded) the thing takes much longer
Jason Frey
@Fryguy
Feb 02 2016 22:25
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
yea, I think I know the code
at least for features and expanding trees
Jason Frey
@Fryguy
Feb 02 2016 22:25
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
@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
yeah, I was suggesting just removing "private" in the code...for now
Keenan Brock
@kbrock
Feb 02 2016 22:28
yup
Jason Frey
@Fryguy
Feb 02 2016 22:28
(btw, this was a cool trip down memory lane...I spent ages on that BZ :grin:)
Keenan Brock
@kbrock
Feb 02 2016 22:28
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
@chessbyte I think that was around when I did the first xnode refactoring
Joe Rafaniello
@jrafanie
Feb 02 2016 22:29
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
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
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
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
@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
so, rubyprof is reporting it wrong?
Keenan Brock
@kbrock
Feb 02 2016 23:08
@jrafanie sorry - different problem
my profiler was messing up when profiling recursive functions
Joe Rafaniello
@jrafanie
Feb 02 2016 23:08
ok
Keenan Brock
@kbrock
Feb 02 2016 23:08
@jrafanie yes - I think there is something wrong in there
Joe Rafaniello
@jrafanie
Feb 02 2016 23:08
So, we're also instantiating the same vms twice
Keenan Brock
@kbrock
Feb 02 2016 23:08
yes
first page rendering:
Rendering: layouts/exp_atom/_editor 2871.2 2871.2
Joe Rafaniello
@jrafanie
Feb 02 2016 23:09
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
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
not more than 5 % though, so probably not a big deal
Keenan Brock
@kbrock
Feb 02 2016 23:09
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
I'm looking at the whole thing in rubyprof
Keenan Brock
@kbrock
Feb 02 2016 23:11
what is your script?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:11
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
ooh - cool
Joe Rafaniello
@jrafanie
Feb 02 2016 23:12
change for your path
it dumps a few htmls on each request
it's slow though
Keenan Brock
@kbrock
Feb 02 2016 23:13
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
I went with 2.1
Keenan Brock
@kbrock
Feb 02 2016 23:13
k
then it runs?
Joe Rafaniello
@jrafanie
Feb 02 2016 23:13
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
yea - not a fan of associations :(
Joe Rafaniello
@jrafanie
Feb 02 2016 23:14
but again, not much more than 3 % of the total time
Keenan Brock
@kbrock
Feb 02 2016 23:14
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
Good night
Dennis Metzger
@dmetzger57
Feb 02 2016 23:21
‘night @jrafanie