Project

General

Profile

Actions

Bug #21964

closed

accessible_resource makes host form very slow

Added by Timo Goebel over 6 years ago. Updated over 5 years ago.

Status:
Closed
Priority:
Normal
Assignee:
Category:
Host creation
Target version:
Difficulty:
Triaged:
No
Fixed in Releases:
Found in Releases:

Description

I have investigated slow rendering of the create host form. Page rendering took over one second. For a form. That's pretty bad.

I narrowed it down to accessible_resource.
When adding the following debug code:

def accessible_resource(obj, resource, order = :name, association: resource)
start = Time.now
[...]
duration = (Time.now - start) * 1000
Rails.logger.info "#{controller_name}##{action_name} -> #{__method__} (#{resource} [#{list.size}]): complete: #{duration} ms" 

Shows the following in a production setup with a fast postgres and no traffic on this application server (8 cores, 32 gb ram):

2017-12-13 19:30:04 0febf00c [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 53.412486 ms
2017-12-13 19:30:04 0febf00c [app] [I] hosts#new -> accessible_resource (hostgroup [142]): complete: 50.485622 ms
2017-12-13 19:30:04 0febf00c [app] [I] hosts#new -> accessible_resource (compute_resource [12]): complete: 51.366071 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (environment [63]): complete: 24.360932 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (realm [1]): complete: 19.958417999999998 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 6.319998 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 5.165922 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (domain [10]): complete: 20.913355000000003 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (Subnet::Ipv4 [73]): complete: 55.331271 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (Subnet::Ipv6 [2]): complete: 29.389371 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (domain [10]): complete: 6.37227 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (Subnet::Ipv4 [73]): complete: 8.826916 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (Subnet::Ipv6 [2]): complete: 7.112331999999999 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (architecture [2]): complete: 12.670696 ms
2017-12-13 19:30:05 0febf00c [app] [I] hosts#new -> accessible_resource (model [15]): complete: 15.766551999999999 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 54.287351 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (hostgroup [142]): complete: 52.016424 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (compute_resource [12]): complete: 62.069528 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (environment [63]): complete: 24.715348000000002 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (realm [1]): complete: 20.959273 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 7.982464 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (smart_proxy [25]): complete: 6.361404 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (domain [10]): complete: 22.146929 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (Subnet::Ipv4 [73]): complete: 52.991576 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (Subnet::Ipv6 [2]): complete: 26.410471 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (domain [10]): complete: 5.997154999999999 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (Subnet::Ipv4 [73]): complete: 8.250084 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (Subnet::Ipv6 [2]): complete: 6.461389 ms
2017-12-13 19:30:14 fbeb8fda [app] [I] hosts#new -> accessible_resource (architecture [2]): complete: 12.776512 ms
2017-12-13 19:30:15 fbeb8fda [app] [I] hosts#new -> accessible_resource (model [15]): complete: 74.358535 ms

It's pretty obvious that we have to optimize this. 75ms to get 15 records from the db is not very good.

The smoking gun looks like this:
accessible_resource_records(resource, order).to_a

It's much faster if we call:
accessible_resource_records(resource, order).pluck(:name, id)

This might actually be enough for a lot of select fields.

Actions #1

Updated by The Foreman Bot over 6 years ago

  • Status changed from New to Ready For Testing
  • Assignee set to Timo Goebel
  • Pull request https://github.com/theforeman/foreman/pull/5095 added
Actions #2

Updated by The Foreman Bot over 5 years ago

  • Pull request https://github.com/theforeman/foreman/pull/6321 added
Actions #3

Updated by Ohad Levy over 5 years ago

  • Target version set to 1.21.0
  • Pull request deleted (https://github.com/theforeman/foreman/pull/5095)
  • Fixed in Releases 1.21.0 added

removing WIP PR from this issue, if its still relevant please open a new issue for it.

Actions #4

Updated by Anonymous over 5 years ago

  • Status changed from Ready For Testing to Closed
Actions

Also available in: Atom PDF