Server slow - InterfaceCloning?

Polle · September 25, 2020, 8:32am

Running Foreman on a DL380p Gen9 - 2x Xeon® CPU E5-2690 0 @ 2.90GHz, 128GB of memory. I guess that configuration should be able to handle a truckload of clients.

Initially, GUI response was very fast, likewise for provisioning, puppet runs … but after connecting a few hundred clients and 2 proxies, things became really slow. What I see that there are constantly a number of ruby processes running, each taking 100% CPU. I installed foreman-tracer and when I run foreman-tracer rails time that returns (top lines only):
FILENAME LINE METHOD TIME
/usr/share/foreman/app/models/concerns/interface_cloning.rb 10 dup 27680034
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/clock.rb 16 where 76290
oot/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/persistence_adapters/sequel.rb 189 pull_envelopes 8018
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-1.4.6/lib/dynflow/clock.rb 16 lambda 2861
/usr/share/foreman/app/models/concerns/interface_cloning.rb 13 keys 792
/usr/share/foreman/app/models/concerns/interface_cloning.rb 11 block_given? 707
/usr/share/foreman/app/models/concerns/interface_cloning.rb 13 - 631
/usr/share/foreman/app/models/concerns/interface_cloning.rb 13 each 549
…

Looks like it is spending most of its time in that interface_cloning.rb script especially on the ‘object.dup’ command on line 10 and I guess that’s what is taking down the performance. I’m trying to figure out how to solve that but I’d welcome some suggestions …

lzap · September 25, 2020, 10:36am

Can you make this change:

diff --git a/app/models/concerns/interface_cloning.rb b/app/models/concerns/interface_cloning.rb
index e0c3dad25..ab0dc1312 100644
--- a/app/models/concerns/interface_cloning.rb
+++ b/app/models/concerns/interface_cloning.rb
@@ -3,6 +3,7 @@ module InterfaceCloning
   # we keep the before update host object in order to compare changes
   def setup_clone(&block)
     return if new_record?
+    Rails.logger.info "Called setup_clone: #{caller}"
     @old = setup_object_clone(self, &block)
   end

Restart for just a bit of time and then put it back. This can easily flood your production.log. Paste one callstack to see what is causing this method to be called so many times.

Do you have any clients reporting many NICs? Like a hypervisors of container with lot of bridge network devices?

I you are able to connect to SQL database, find hosts which has most NICs and show the result. Often, there can be just a single offender with 10000 NICs that slows everything down.

Polle · September 28, 2020, 8:07am

Thx for looking into this - I made the change and attached a log.
I do see lots of messages like:
2020-09-28T09:59:13 [I|aud|9f24504f] Nic::Managed (17208) update event on attached_to br-39.126-lif1, br-39.151-lif1
2020-09-28T09:59:13 [I|aud|9f24504f] Nic::Managed (17208) update event on identifier br-39.126-lif1.1064, br-39.151-lif1.1064
2020-09-28T09:59:14 [I|aud|3023f528] Nic::Managed (32903) update event on attached_to br-39.206-lif1, br-39.28-lif1
2020-09-28T09:59:14 [I|aud|3023f528] Nic::Managed (32903) update event on identifier br-39.206-lif1.1061, br-39.28-lif1.1061
2020-09-28T09:59:14 [I|aud|219e6ce1] Nic::Managed (35549) update event on attached_to br-111.61-lif1, br-111.62-lif1
2020-09-28T09:59:14 [I|aud|219e6ce1] Nic::Managed (35549) update event on identifier br-111.61-lif1.1068, br-111.62-lif1.1068

I don’t have a detailed view of what is being run on all those servers but it involves creation of docker containers on the fly & running test procedures so I guess there might be quite a few bridge interfaces involved.

Polle · September 28, 2020, 8:17am

I can connect to the database - I’m pretty familiar with SQL so if you can give me a few hints on which tables / fields to query I’ll give it a shot.
Wrongly thought I could attach a file - here’s a call stack:

2020-09-28T09:06:48 [I|app|f1e77176] Called setup_clone: ["/usr/share/foreman/app/models/host/base.rb:361:in setup_clone'", "/usr/share/foreman/app/models/nic/managed.rb:117:in setup_clone’", “/usr/share/foreman/app/models/concerns/orchestration.rb:85:in valid?'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/validations.rb:84:in perform_validations’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/validations.rb:52:in save!'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:315:in block in save!’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:387:in block in with_transaction_returning_status'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in block in transaction’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:239:in block in within_new_transaction'", "/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in mon_synchronize’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/transaction.rb:236:in within_new_transaction'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/connection_adapters/abstract/database_statements.rb:254:in transaction’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:212:in transaction'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:385:in with_transaction_returning_status’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/transactions.rb:315:in save!'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/suppressor.rb:48:in save!’”, “/usr/share/foreman/app/models/host/base.rb:569:in block in update_virtuals'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation/delegation.rb:41:in each’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/relation/delegation.rb:41:in each'", "/usr/share/foreman/app/models/host/base.rb:564:in update_virtuals’”, “/usr/share/foreman/app/models/host/base.rb:545:in set_interface'", "/usr/share/foreman/app/models/host/base.rb:229:in block in set_interfaces’”, “/usr/share/foreman/app/models/host/base.rb:226:in each'", "/usr/share/foreman/app/models/host/base.rb:226:in set_interfaces’”, “/usr/share/foreman/app/models/host/base.rb:194:in populate_fields_from_facts'", "/usr/share/foreman/app/models/host/managed.rb:424:in populate_fields_from_facts’”, “/usr/share/foreman/app/models/concerns/puppet_host_extensions.rb:3:in populate_fields_from_facts'", "/usr/share/foreman/app/models/host/base.rb:168:in block in parse_facts’”, “/usr/share/foreman/app/services/foreman/telemetry_helper.rb:27:in telemetry_duration_histogram'", "/usr/share/foreman/app/models/host/base.rb:167:in parse_facts’”, “/usr/share/foreman/app/models/host/base.rb:153:in import_facts'", "/usr/share/foreman/app/models/host/managed.rb:343:in import_facts’”, “/usr/share/foreman/app/controllers/api/v2/hosts_controller.rb:286:in facts'", "/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/basic_implicit_render.rb:6:in send_action’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/base.rb:194:in process_action'", "/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rendering.rb:30:in process_action’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:42:in block in process_action'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:109:in block in run_callbacks’”, “/usr/share/foreman/app/controllers/api/v2/base_controller.rb:163:in disable_json_root'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/usr/share/foreman/app/controllers/concerns/foreman/controller/timezone.rb:10:in set_timezone'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/usr/share/foreman/app/models/concerns/foreman/thread_session.rb:32:in clear_thread'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/usr/share/foreman/app/controllers/concerns/foreman/controller/topbar_sweeper.rb:12:in set_topbar_sweeper_controller'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in around'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/audited-4.9.0/lib/audited/sweeper.rb:14:in around'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:118:in block in run_callbacks’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/callbacks.rb:136:in run_callbacks'", "/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/abstract_controller/callbacks.rb:41:in process_action’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/rescue.rb:22:in process_action'", "/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:34:in block in process_action’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in block in instrument'", "/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications/instrumenter.rb:23:in instrument’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-5.2.1/lib/active_support/notifications.rb:168:in instrument'", "/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/instrumentation.rb:32:in process_action’”, “/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-5.2.1/lib/action_controller/metal/params_wrapper.rb:256:in `process_action’”, "/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-5.2.1/lib/active_record/railties/controller_runtime.rb:2

Polle · September 28, 2020, 8:59am

Some pretty high numbers imho …

foreman=# select count(id) from nics where identifier like 'br-%' group by host_id;
 count
-------
     2
     8
   818
    10
    23
    38
   836
   317
     1
     1
   329
   103
   695
   972
  1967
   144
    62
     1
    27
   857
    64
     6
     1
    14
   109
     3
     3
     5
     2
     7
   262
     1
     4
    64
     2
     2
     1
     4
   124
    73
    64
   209
     4
     1
     4
     1
   947
     2
     8
   852
     4
   225
     1
     4
     2
    16
    92
    61
    44
   799
     2
   139
   802
   165
   114
     1
     2
    53
     1
    30
    59
    67
    82
    64
     2
   989
     2
     1
     1
     6
     2
     1
     4
    60
    37
     1
     5
    28
     4
     1
   166
    26
   636
     1
   675
    37
     1
     2
    34
   111
     2
     6
    34
    19
     3
    10
   113
     3
    48
   122
    48
    59
     5
   884
    65
    47
   950
    29
     4
(119 rows)

lzap · September 30, 2020, 6:09am

Yeah, some of your host(s) have many bridge interfaces which fills up database pretty hard. Foreman was designed with hosts with dozens of NICs in mind, if you have hundreds of thousands it gets pretty rough.

Can you tell what kind of software makes these? And what is the pattern to ignore? We have a list of ignored interfaces in Administer - Settings - Provisioning - Ignore interfaces with matching identifier. Add something like br-* to the list to stop adding more interfaces, then find hosts with those and delete them.

You can do this by deleting from table named “nics”: DELETE FROM nics WHERE identifier IS LIKE 'br-%';. Make a backup prior this, I think there are no associations to NIC so you should be fine.

Polle · September 30, 2020, 10:42am

Hi - thx for looking further into this.
I don’t have a detailed view of what’s being run on all those servers but I’m pretty sure those br-* interfaces are being generated by docker runs (some automated build processes).
I already tried that delete query and that indeed pumps up the speed - I noticed right after the delete that the br-* started re-appearing. I updated the ‘Exclude pattern for facts stored in foreman’ setting but overlooked the one about ‘Ignore interfaces …’ - that should prevent them from re-appearing I guess.
If those br- interfaces are default names, it might by useful to add them do the default list for the exclude and ignore settings maybe …

Thx again - looks like this will solve the performance issue.

lzap · October 1, 2020, 12:33pm

Yeah we have two filters, one for facts and one for NICs. We hope to improve this someday.