Bug #16749: Foreman performs extremely slowly when a puppet agent with a high number of IP addresses configured reports in - Foreman

Actions

Copy link

Bug #16749

closed

Foreman performs extremely slowly when a puppet agent with a high number of IP addresses configured reports in

Added by Eduardo Mayoral over 8 years ago. Updated almost 7 years ago.

Status:

Closed

Priority:

Normal

Assignee:

Dominic Cleal

Category:

Importers

Target version:

1.13.1

Difficulty:

medium

Triaged:

Bugzilla link:

Pull request:

https://github.com/theforeman/foreman/pull/3909

Fixed in Releases:

Found in Releases:

1.12.3

Red Hat JIRA:

Description

I have a foreman installation with about 900 puppet agents connecting to it. A few of them have a high number of local IP adresses (in the range of 300-500)

When one of these agents reports in, processing time for that request is very slow (about 12 seconds, as compared to about 0.4 seconds for a typical agent with 1 or 2 IP addresses), the CPU usage for the foreman server process goes very high (at or around 100%) and the memory usage of the foreman process increases a lot.

This happens with several agents and the common factor seems to be the high number of local IP addresses.

Relevant production.log lines:

2016-09-30 07:33:45 [app] [I] Started POST "/api/hosts/facts" for 217.76.129.21 at 2016-09-30 07:33:45 +0200
2016-09-30 07:33:45 [app] [I] Processing by Api::V2::HostsController#facts as JSON
2016-09-30 07:33:45 [app] [I] Parameters: {"name"=>"dnsp12.servidoresdns.net", "facts"=>"[FILTERED]", "certname"=>"dnsp12.servidoresdns.net", "apiv"=>"v2", :host=>{"name"=>"dnsp12.servidoresdns.net", "certname"=>"dnsp12.servidoresdns.net"}}
2016-09-30 07:34:09 [app] [I] Completed 201 Created in 24556ms (Views: 10.0ms | ActiveRecord: 7663.3ms)
2016-09-30 07:34:09 [app] [I] Started GET "/node/dnsp12.servidoresdns.net?format=yml" for 217.76.129.21 at 2016-09-30 07:34:09 +0200
2016-09-30 07:34:09 [app] [I] Processing by HostsController#externalNodes as YML
2016-09-30 07:34:09 [app] [I] Parameters: {"name"=>"dnsp12.servidoresdns.net"}

Files

production-debug.log.tar.xz

181 KB

Eduardo Mayoral, 10/03/2016 05:39 AM

Updated by Dominic Cleal over 8 years ago

Category changed from Puppet integration to Importers

Updated by Eduardo Mayoral over 8 years ago

File production-debug.log.tar.xz production-debug.log.tar.xz added

Updated by Dominic Cleal over 8 years ago

Thanks, that's very helpful. It looks like the NIC updates themselves take a long time to complete.

There are two long loops - once retrieving the facts per interface in the parser, and the second when saving each NIC in turn.

2016-10-03 11:33:55 [app] [I] Processing by Api::V2::HostsController#facts as JSON
2016-10-03 11:33:55 [app] [I]   Parameters: {"certname"=>"dnsp12.servidoresdns.net", "name"=>"dnsp12.servidoresdns.net", "facts"=>"[FILTERED]", "apiv"=>"v2", :host=>{"name"=>"dnsp12.servidoresdns.net", "certname"=>"dnsp12.servidoresdns.net"}}
2016-10-03 11:33:55 [sql] [D]   Host::Managed Load (0.4ms)  SELECT  `hosts`.* FROM `hosts` WHERE `hosts`.`type` IN ('Host::Managed') AND `hosts`.`certname` = 'dnsp12.servidoresdns.net' LIMIT 1
2016-10-03 11:33:55 [app] [D] Merging facts for 'dnsp12.servidoresdns.net': deleted 0 facts
2016-10-03 11:33:55 [app] [D] Merging facts for 'dnsp12.servidoresdns.net': added 0 facts
2016-10-03 11:33:55 [app] [D] Merging facts for 'dnsp12.servidoresdns.net': updated 9 facts
2016-10-03 11:33:55 [app] [I] Import facts for 'dnsp12.servidoresdns.net' completed. Added: 0, Updated: 9, Deleted 0 facts
2016-10-03 11:33:56 [app] [D] We have following interfaces 'eth0, eth0_1, eth0_2, [..], eth0_790, sit0' based on facts
2016-10-03 11:33:56 [app] [D] Interface eth0 facts: {"netmask"=>"255.255.254.0", "network"=>"82.223.86.0", "mtu"=>"1500", "macaddress"=>"00:50:56:A6:39:14", "ipaddress"=>"82.223.87.46"}
[..]
2016-10-03 11:34:07 [app] [D] Interface eth0_753 facts: {"network"=>"217.76.140.0", "ipaddress"=>"217.76.141.223", "netmask"=>"255.255.254.0", "macaddress"=>"00:50:56:A6:39:14", "mtu"=>"1500"}
2016-10-03 11:34:07 [sql] [D] Saving eth0 NIC for host dnsp12.servidoresdns.net
2016-10-03 11:34:07 [sql] [D] Saving sit0 NIC for host dnsp12.servidoresdns.net
2016-10-03 11:34:07 [sql] [D] Saving eth0.1 NIC for host dnsp12.servidoresdns.net
[..]
2016-10-03 11:34:20 [sql] [D] Saving eth0.790 NIC for host dnsp12.servidoresdns.net
2016-10-03 11:34:21 [app] [I] Completed 201 Created in 26698ms (Views: 13.5ms | ActiveRecord: 7733.0ms)

Saving happens in many separate transactions:

2016-10-03 11:34:07 [sql] [D]   Nic::Base Load (0.5ms)  SELECT  `nics`.* FROM `nics` WHERE `nics`.`host_id` = 613 AND `nics`.`mac` = '00:50:56:a6:39:14' AND `nics`.`virtual` = 1 AND `nics`.    `identifier` = 'eth0.7'  ORDER BY `nics`.`identifier` ASC LIMIT 1
2016-10-03 11:34:07 [sql] [D] Saving eth0.7 NIC for host dnsp12.servidoresdns.net
2016-10-03 11:34:07 [sql] [D]    (0.1ms)  BEGIN
2016-10-03 11:34:07 [sql] [D]   Nic::Base Load (17.3ms)  SELECT `nics`.* FROM `nics` WHERE `nics`.`ip` = '82.223.91.251'
2016-10-03 11:34:07 [sql] [D] Using nic queue
2016-10-03 11:34:07 [sql] [D]    (0.1ms)  COMMIT