Bug #21964
closedaccessible_resource makes host form very slow
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.
Updated by The Foreman Bot almost 7 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
Updated by The Foreman Bot almost 6 years ago
- Pull request https://github.com/theforeman/foreman/pull/6321 added
Updated by Ohad Levy almost 6 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.
Updated by Anonymous almost 6 years ago
- Status changed from Ready For Testing to Closed
Applied in changeset 6c1f956348bcc793adf767a03bc20cef884dc752.