Bug #3145
closed
Performance issue editing host with many parameters
Description
Hi,
I am having an issue where Foreman is acting very slow.
Clicking edit on a host will for example take around 27.5 seconds, but other actions are slow as well, Updating/reading from the API for instance.
I am only using Foreman with puppet, so no compute resources or host management.
The issue is both in 1.1 and 1.2.
I am running Foreman via passenger (webrick isnt any faster, upgraded to passenger to see if that helped, which it didnt), with a mysql backend.
The mysql server have around 0.04 in load with no IO.
I have also tried running with the various memcached settings, but it will only cache around 6000 bytes at max, and no performance improvements.
I am not sure where to start to debug this.
Files
Updated by Ohad Levy over 10 years ago
could you turn on debugging and paste log entries from the slow requests? see Troubleshooting for turning on debug
Updated by Espen Fjellvær Olsen over 10 years ago
Oh.. This was interesting..
It seems that there is a tonne of "CACHE (0.0ms) SELECT `hostgroups`.* FROM `hostgroups` WHERE `hostgroups`.`id` IN (1) AND (1=1) ORDER BY (case when hostgroups.ancestry is null then 0 else 1 end), hostgroups.ancestry" taking all the time.
I have prepended some timings to the debug logging to really show where it is using time.
Updated by Ohad Levy over 10 years ago
Indeed that does not seem right.. do you have an extremely large number of puppet classes, or hostgroups or something like that?
is it connected to a Compute Resource? any chance its the connectivity which is slow ?
does it happens it all hosts? (also if you click on new host vs edit)
Updated by Espen Fjellvær Olsen over 10 years ago
From the database I see that I have 430 puppetclasses, 484 host groups, 774 hosts, 68038 facts, 1060866 reports etc.
No connection to any compute resource (it should be totally disabled as far as I can see).
All hosts are placed in a hostgroup (One or more hosts per hostgroup) which inherits from one global host group.
Clicking the new button to create a new hosts also takes around 10-15 seconds, and hitting edit on that again after its created also takes 20+ seconds, regardless of it having a hostgroup or not.
As you can see from the debug log the 8125
"CACHE (0.0ms) SELECT `hostgroups`.* FROM `hostgroups` WHERE `hostgroups`.`id` IN (1) AND (1=1) ORDER BY (case when hostgroups.ancestry is null then 0 else 1 end), hostgroups.ancestry" lines take all the time, and there are sometimes a second++ gap between them: "2013-09-25 06-32-38-903 CACHE (0.0ms) SELECT `hostgroups`.* FROM `hostgroups` WHERE `hostgroups`.`id` IN (1) AND (1=1) ORDER BY (case when hostgroups.ancestry is null then 0 else 1 end), hostgroups.ancestry 2013-09-25 06-32-41-037 CACHE (0.0ms) SELECT `hostgroups`.* FROM `hostgroups` WHERE `hostgroups`.`id` IN (1) AND (1=1) ORDER BY (case when hostgroups.ancestry is null then 0 else 1 end), hostgroups.ancestry"
Updated by Dan Hawke over 8 years ago
Hi, did you ever manage to find a solution to this? We have 294 puppetclasses, but currently only 1 hostgroup and 25 hosts and are seeing similar slowness on editing Hosts compared to an otherwise responsive interface. We do have a connection to a VMware compute resource.
We are running on Foreman 1.8.1 on RHEL6.6, 8GB RAM, 2vCPU.
Did you require any more debug info?
2015-08-12 09:54:46 [I]
Started GET "/hosts/[clientname]/edit" for 192.168.109.78 at 2015-08-12 09:54:46 +1200
2015-08-12 09:54:46 [I] Processing by HostsController#edit as HTML
2015-08-12 09:54:46 [I] Parameters: {"id"=>"[clientname]"}
2015-08-12 09:54:46 [I] Rendered hosts/_progress.html.erb (0.1ms)
2015-08-12 09:54:46 [I] Rendered puppetclasses/_selectedClasses.html.erb (1.4ms)
2015-08-12 09:54:46 [I] Rendered puppetclasses/_classes_in_groups.html.erb (0.0ms)
2015-08-12 09:54:46 [I] Rendered puppetclasses/_classes.html.erb (383.8ms)
2015-08-12 09:54:46 [I] Rendered puppetclasses/_class_selection.html.erb (446.1ms)
2015-08-12 09:54:46 [I] Successfully decrypted field for Foreman::Model::Vmware [vCentername]
2015-08-12 09:54:47 [I] Connecting to database specified by database.yml
2015-08-12 09:54:48 [I]
Started GET "/node/[clientname]?format=yml" for 10.102.1.61 at 2015-08-12 09:54:48 +1200
2015-08-12 09:54:48 [I] Processing by HostsController#externalNodes as YML
2015-08-12 09:54:48 [I] Parameters: {"name"=>"[clientname]"}
2015-08-12 09:54:49 [I] Rendered text template (0.0ms)
2015-08-12 09:54:49 [I] Completed 200 OK in 293ms (Views: 0.7ms | ActiveRecord: 10.0ms)
2015-08-12 09:54:52 [I] Rendered compute_resources_vms/form/vmware/_base.html.erb (4911.8ms)
2015-08-12 09:54:53 [I] Rendered compute_resources_vms/form/vmware/_volume.html.erb (1387.4ms)
2015-08-12 09:54:53 [W] Creating scope :completer_scope. Overwriting existing method Organization.completer_scope.
2015-08-12 09:54:53 [W] Creating scope :completer_scope. Overwriting existing method Location.completer_scope.
2015-08-12 09:54:55 [I] Rendered compute_resources_vms/form/vmware/_volume.html.erb (1315.5ms)
2015-08-12 09:54:56 [I] Rendered compute_resources_vms/form/vmware/_volume.html.erb (1327.2ms)
2015-08-12 09:54:56 [I] Rendered compute_resources_vms/form/_volumes.html.erb (4358.3ms)
2015-08-12 09:54:56 [I] Rendered hosts/_compute_detail.html.erb (9271.1ms)
2015-08-12 09:54:56 [I] Rendered hosts/_compute.html.erb (9451.8ms)
2015-08-12 09:54:56 [I] Rendered nic/_base_form.html.erb (13.1ms)
2015-08-12 09:54:56 [I] Rendered nic/_virtual_form.html.erb (1.3ms)
2015-08-12 09:54:57 [I] Rendered compute_resources_vms/form/vmware/_network.html.erb (1459.2ms)
2015-08-12 09:54:57 [I] Rendered nic/_provider_specific_form.html.erb (1461.0ms)
2015-08-12 09:54:57 [I] Rendered nic/manageds/_managed.html.erb (1477.7ms)
2015-08-12 09:54:57 [I] Rendered nic/_base_form.html.erb (140.3ms)
2015-08-12 09:54:58 [I] Rendered nic/_virtual_form.html.erb (1.4ms)
2015-08-12 09:54:59 [I] Rendered compute_resources_vms/form/vmware/_network.html.erb (1548.2ms)
2015-08-12 09:54:59 [I] Rendered nic/_provider_specific_form.html.erb (1549.3ms)
2015-08-12 09:54:59 [I] Rendered nic/manageds/_managed.html.erb (1693.6ms)
2015-08-12 09:54:59 [I] Rendered hosts/_interfaces.html.erb (3174.4ms)
2015-08-12 09:54:59 [I] Rendered common/os_selection/_architecture.html.erb (3.7ms)
2015-08-12 09:54:59 [I] Rendered common/os_selection/_operatingsystem.html.erb (9.3ms)
2015-08-12 09:54:59 [I] Rendered hosts/_operating_system.html.erb (19.0ms)
2015-08-12 09:54:59 [I] Rendered hosts/_unattended.html.erb (12648.7ms)
2015-08-12 09:54:59 [I] Rendered puppetclasses/_class_parameters.html.erb (0.0ms)
2015-08-12 09:54:59 [I] Rendered puppetclasses/_classes_parameters.html.erb (9.4ms)
2015-08-12 09:54:59 [I] Rendered common_parameters/_inherited_parameters.html.erb (0.6ms)
2015-08-12 09:54:59 [I] Rendered common_parameters/_puppetclass_parameter.html.erb (3.0ms)
2015-08-12 09:54:59 [I] Rendered common_parameters/_puppetclasses_parameters.html.erb (7.5ms)
2015-08-12 09:54:59 [I] Rendered common_parameters/_parameter.html.erb (1.7ms)
2015-08-12 09:54:59 [I] Rendered common_parameters/_parameters.html.erb (5.4ms)
2015-08-12 09:54:59 [I] Rendered hosts/_form.html.erb (13174.4ms)
2015-08-12 09:54:59 [I] Rendered hosts/edit.html.erb within layouts/application (13176.7ms)
2015-08-12 09:54:59 [I] Rendered home/_user_dropdown.html.erb (4.5ms)
2015-08-12 09:54:59 [I] Read fragment views/tabs_and_title_records-3 (0.1ms)
2015-08-12 09:54:59 [I] Rendered home/_org_switcher.html.erb (0.0ms)
2015-08-12 09:54:59 [I] Rendered home/_submenu.html.erb (2.8ms)
2015-08-12 09:54:59 [I] Rendered home/_submenu.html.erb (8.4ms)
2015-08-12 09:54:59 [I] Rendered home/_submenu.html.erb (2.3ms)
2015-08-12 09:54:59 [I] Rendered home/_submenu.html.erb (4.5ms)
2015-08-12 09:54:59 [I] Rendered home/_submenu.html.erb (203.2ms)
2015-08-12 09:54:59 [I] Write fragment views/tabs_and_title_records-3 (1.5ms)
2015-08-12 09:54:59 [I] Rendered home/_topbar.html.erb (236.3ms)
2015-08-12 09:54:59 [I] Rendered layouts/base.html.erb (238.0ms)
2015-08-12 09:54:59 [I] Completed 200 OK in 13433ms (Views: 13397.9ms | ActiveRecord: 21.5ms)
2015-08-12 09:54:59 [I]
Started GET "/hosts/[clientname]/edit" for 192.168.109.78 at 2015-08-12 09:54:59 +1200
2015-08-12 09:54:59 [I] Processing by HostsController#edit as HTML
2015-08-12 09:54:59 [I] Parameters: {"id"=>"[clientname]"}
2015-08-12 09:54:59 [I] Rendered hosts/_progress.html.erb (0.2ms)
2015-08-12 09:55:00 [I] Rendered puppetclasses/_selectedClasses.html.erb (1.5ms)
2015-08-12 09:55:00 [I] Rendered puppetclasses/_classes_in_groups.html.erb (0.0ms)
2015-08-12 09:55:00 [I] Rendered puppetclasses/_classes.html.erb (589.1ms)
2015-08-12 09:55:00 [I] Rendered puppetclasses/_class_selection.html.erb (666.2ms)
2015-08-12 09:55:00 [I]
Started POST "/api/hosts/facts" for 10.102.1.61 at 2015-08-12 09:55:00 +1200
2015-08-12 09:55:00 [I] Successfully decrypted field for Foreman::Model::Vmware [vCentername]
2015-08-12 09:55:00 [I] Processing by Api::V2::HostsController#facts as JSON
2015-08-12 09:55:00 [I] Parameters: {"name"=>"[clientname]", "facts"=>"[FILTERED]", "certname"=>"[clientname]", "apiv"=>"v2", :host=>{"name"=>"[clientname]", "certname"=>"[clientname]"}}
2015-08-12 09:55:00 [I] Import facts for '[clientname]' completed. Added: 0, Updated: 5, Deleted 0 facts
2015-08-12 09:55:01 [I] Completed 201 Created in 365ms (Views: 2.2ms | ActiveRecord: 0.0ms)
2015-08-12 09:55:01 [I]
Started GET "/node/[clientname]?format=yml" for 10.102.1.61 at 2015-08-12 09:55:01 +1200
2015-08-12 09:55:01 [I] Processing by HostsController#externalNodes as YML
2015-08-12 09:55:01 [I] Parameters: {"name"=>"[clientname]"}
2015-08-12 09:55:01 [I] Rendered text template (0.0ms)
2015-08-12 09:55:01 [I] Completed 200 OK in 388ms (Views: 0.8ms | ActiveRecord: 10.4ms)
2015-08-12 09:55:02 [I]
Updated by Jeff Sault over 8 years ago
This may or may not be related to the original issue but it looks like performance has dropped significantly somewhere between foreman 1.6 and 1.8.1. We are seeing page render times of over 3 MINUTES when trying to edit hosts with a large number of class parameters (~400), even only with a handful of hostgroups
2015-09-01 11:13:57 [I] Rendered puppetclasses/_class_parameters.html.erb (181876.2ms) 2015-09-01 11:13:57 [I] Rendered puppetclasses/_classes_parameters.html.erb (182157.2ms) 2015-09-01 11:13:57 [I] Rendered common_parameters/_inherited_parameters.html.erb (1.9ms) 2015-09-01 11:14:00 [I] Rendered common_parameters/_puppetclass_parameter.html.erb (2908.9ms) 2015-09-01 11:14:00 [I] Rendered common_parameters/_puppetclasses_parameters.html.erb (2921.3ms) 2015-09-01 11:14:00 [I] Rendered common_parameters/_parameter.html.erb (16.7ms) 2015-09-01 11:14:00 [I] Rendered common_parameters/_parameters.html.erb (151.3ms) 2015-09-01 11:14:00 [I] Rendered hosts/_form.html.erb (185953.7ms) 2015-09-01 11:14:00 [I] Rendered hosts/edit.html.erb within layouts/application (186180.6ms) 2015-09-01 11:14:00 [I] Rendered home/_user_dropdown.html.erb (12.2ms) 2015-09-01 11:14:00 [I] Read fragment views/tabs_and_title_records-3 (0.1ms) 2015-09-01 11:14:00 [I] Rendered home/_org_switcher.html.erb (0.9ms) 2015-09-01 11:14:00 [I] Rendered home/_submenu.html.erb (9.2ms) 2015-09-01 11:14:00 [I] Rendered home/_submenu.html.erb (9.6ms) 2015-09-01 11:14:00 [I] Rendered home/_submenu.html.erb (6.7ms) 2015-09-01 11:14:00 [I] Rendered home/_submenu.html.erb (8.0ms) 2015-09-01 11:14:00 [I] Rendered home/_submenu.html.erb (7.4ms) 2015-09-01 11:14:00 [I] Write fragment views/tabs_and_title_records-3 (2.7ms) 2015-09-01 11:14:00 [I] Rendered home/_topbar.html.erb (73.6ms) 2015-09-01 11:14:00 [I] Rendered layouts/base.html.erb (79.6ms) 2015-09-01 11:14:00 [I] Completed 200 OK in 186603ms (Views: 180047.8ms | ActiveRecord: 6490.8ms)
Enabling debug shows an insane number of SQL queries. In my test the debug log for a single page render was ~65,000 lines long. Most of the lines were similar to this..
2015-09-01 11:05:58 [D] CACHE (0.0ms) SELECT "lookup_values"."id" AS t0_r0, "lookup_values"."match" AS t0_r1, "lookup_values"."value" AS t0_r2, "lookup_values"."lookup_key_id" AS t0_r3, "lookup_values"."created_at" AS t0_r4, "lookup_values"."updated_at" AS t0_r5, "lookup_values"."use_puppet_default" AS t0_r6, "lookup_keys"."id" AS t1_r0, "lookup_keys"."key" AS t1_r1, "lookup_keys"."created_at" AS t1_r2, "lookup_keys"."updated_at" AS t1_r3, "lookup_keys"."puppetclass_id" AS t1_r4, "lookup_keys"."default_value" AS t1_r5, "lookup_keys"."path" AS t1_r6, "lookup_keys"."description" AS t1_r7, "lookup_keys"."validator_type" AS t1_r8, "lookup_keys"."validator_rule" AS t1_r9, "lookup_keys"."is_param" AS t1_r10, "lookup_keys"."key_type" AS t1_r11, "lookup_keys"."override" AS t1_r12, "lookup_keys"."required" AS t1_r13, "lookup_keys"."lookup_values_count" AS t1_r14, "lookup_keys"."merge_overrides" AS t1_r15, "lookup_keys"."avoid_duplicates" AS t1_r16, "lookup_keys"."use_puppet_default" AS t1_r17 FROM "lookup_values" LEFT OUTER JOIN "lookup_keys" ON "lookup_keys"."id" = "lookup_values"."lookup_key_id" WHERE "lookup_values"."match" IN ('fqdn=mspi-02-srv02.mspu.hq.k.grp', 'hostgroup=SDP', 'environment=ML28', 'all_environments=true', 'default_parameters_environment=ML28') AND "lookup_values"."lookup_key_id" IN (SELECT "lookup_keys"."id" FROM "lookup_keys" INNER JOIN "environment_classes" ON "environment_classes"."lookup_key_id" = "lookup_keys"."id" WHERE "lookup_keys"."override" = 't' AND "environment_classes"."puppetclass_id" IN (34, 106, 107, 84, 118, 119, 126, 117, 104, 95, 40, 102, 98, 161, 108, 157, 93, 100, 105, 109, 92, 97, 103, 115, 127, 101, 110, 124, 113, 87, 114) AND "environment_classes"."environment_id" = 3 ORDER BY lookup_keys.key) AND "lookup_values"."lookup_key_id" = 677 AND "lookup_values"."use_puppet_default" = 'f'
This is making foreman pretty much unusable for us.
Updated by Dominic Cleal over 8 years ago
- Tracker changed from Support to Bug
- Subject changed from Performance issue to Performance issue editing host with many parameters
- Category set to Performance
- Status changed from New to Ready For Testing
- Pull request https://github.com/theforeman/foreman/pull/2664 added
Updated by Tom Caspy over 8 years ago
- Related to Tracker #11657: Performance refactoring for HostsController added
Updated by Tom Caspy over 8 years ago
- Status changed from Ready For Testing to Closed
- % Done changed from 0 to 100
Applied in changeset 55ee550c02b59e2677600761142de483d2adbf9a.
Updated by Dominic Cleal over 8 years ago
- translation missing: en.field_release set to 63