Project

General

Profile

Bug #3145

Performance issue editing host with many parameters

Added by Espen Fjellvær Olsen almost 6 years ago. Updated about 1 year ago.

Status:
Closed
Priority:
Normal
Assignee:
Category:
Performance
Target version:
Difficulty:
Triaged:
Bugzilla link:
Team Backlog:
Fixed in Releases:
Found in Releases:

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.

debug.log debug.log 1.8 MB Espen Fjellvær Olsen, 09/25/2013 06:36 AM

Related issues

Related to Foreman - Tracker #11657: Performance refactoring for HostsControllerNew2015-09-02

Associated revisions

Revision 55ee550c (diff)
Added by Tom Caspy almost 4 years ago

fixes #3145 - host with a lot of parameters quicker

History

#1 Updated by Ohad Levy almost 6 years ago

could you turn on debugging and paste log entries from the slow requests? see Troubleshooting for turning on debug

#2 Updated by Espen Fjellvær Olsen almost 6 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.

#3 Updated by Ohad Levy almost 6 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)

#4 Updated by Espen Fjellvær Olsen almost 6 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" 

#5 Updated by Dan Hawke about 4 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]

#6 Updated by Jeff Sault almost 4 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.

#7 Updated by Tom Caspy almost 4 years ago

  • Assignee set to Tom Caspy

#8 Updated by Dominic Cleal almost 4 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

#9 Updated by Tom Caspy almost 4 years ago

  • Related to Tracker #11657: Performance refactoring for HostsController added

#10 Updated by Tom Caspy almost 4 years ago

  • Status changed from Ready For Testing to Closed
  • % Done changed from 0 to 100

#11 Updated by Dominic Cleal almost 4 years ago

  • Legacy Backlogs Release (now unused) set to 63

Also available in: Atom PDF