Foreman 2.1.1 optimizing it for thousands of servers/performance issues

Support
1

Problem:
I have a Foreman cluster in scenario Katello with 18 smart proxies. Currently it manages ~4000 VM’s on 18 locations. Used only for package management.
I’m subscribing the rest of the servers which will make the total number of servers closer to 10 000.

I have as per recommendation in documentation raised resources of Foreman main server for tuning profile medium and and ran installer with that option.

When I’m enrolling new servers i see jobs for update facts update take a very long time.

On the other hand, server is nowhere near using CPU and RAM fully. RAM is used up to 12 GB out of 32 GB, and CPU will spike during subscribing of new machines up to 50%, usually being 10-20%.
IO operations take around 100 ms tops in those spikes. Disk for Foreman VM is on flash storage.

Smart proxies show even less performance issues, have more than enough RAM.

But UI breaks apart if this happens. Original installation of this Foreman was when version 1.23 was the latest and was updated regularly ever since, current being latest Foreman 2.1.1/Katello 3.16, if this info is relevant.

Expected outcome:
What can I do to tweak this so facts add/update does not take long, like 16 seconds or so?

Foreman and Proxy versions:

Foreman 2.1.1/Katello 3.16

Foreman and Proxy plugin versions:

Foreman 2.1.1/Katello 3.16

Distribution and version:
CentOS 7.8

Other relevant data:
Example of facts log:
2020-09-09T11:04:36 [I|app|385e6af1] Started PUT “/rhsm/consumers/37dac896-5695-4e47-b703-3fe938a6c34e” for 127.0.0.1 at 2020-09-09 11:04:36 +0000
2020-09-09T11:04:36 [I|app|385e6af1] Processing by Katello::Api::Rhsm::CandlepinProxiesController#facts as JSON
2020-09-09T11:04:36 [I|app|385e6af1] Parameters: {“facts”=>"[FILTERED]", “id”=>“37dac896-5695-4e47-b703-3fe938a6c34e”}
2020-09-09T11:07:24 [I|app|385e6af1] Import facts for ‘server345.domain.local’ completed. Added: 0, Updated: 1, Deleted 0 facts
2020-09-09T11:07:24 [I|app|385e6af1] Completed 200 OK in 167734ms (Views: 0.2ms | ActiveRecord: 212.2ms | Allocations: 1718622)

2

usually the bottleneck lies in the database with the number of fact_names, you can check with psql and look for a huge set of duplicate fact_names

# su - postgres -c "psql foreman -c \"select name from fact_names;\"" > pg_fact_names.log
# awk -F "::" '{ print $1 }' pg_fact_names.log | sort | uniq -c | sort -nr | head -n5
   407683  mountpoints
   345778  partitions
   46945  disks
   11158  net
   6581  networking

If that is the case, you can filter the unneeded facts via:

UI -> Administer -> Settings -> Provisioning -> Exclude pattern for facts stored in Foreman

Then after adding “partitions*, mountpoints*” or whatever other facts you want to filter run:

# foreman-rake interfaces:clean
# foreman-rake facts:clean
5 Likes
3

Mike, welcome back! :slight_smile:

Yeah, we are planning redesign of facts effectively storing just a small portion in tables and the rest in a blob (not searchable). Until this happens, the best bet is fact filter (Exclude pattern for facts stored in foreman - in Administer - Settings). Make sure you exclude those offenders.

We also have Maximum structured facts setting which limits how many subkeys are allowed, for example host with 1000 drives would not get those facts in since it’s above the limit (100 by default). This will only work for modern facts, if your hosts send legacy facts (all in root) it won’t work.

Once you have a single host in the database, some operations can get really slow. Make sure there are no hosts with many facts.

4

Hey, thank you both.
I’ve checked my db and these are my results:

$ awk -F "::" '{ print $1 }' pg_fact_names.log | sort | uniq -c | sort -nr | head -n5
   14155  net
     287  mountpoints
     145  partitions
     100  dmi
      73  ec2_metadata

So I have issues where there is too much network interfaces If I understood correctly?
I usually have on each server loopback, eth0 and docker0 interfaces. So this is causing bottleneck in DB?

5

I took the liberty to slightly edit your comment for better readability. See Fenced Code Blocks and Syntax Highlighting @ Extended Syntax | Markdown Guide.

The net fact surprises me since by default facter uses networking.

docker0 is often a bridge and you have a lot of tap devices as well (for each container). Those are a more likely reason that they’ve been blown up.

Besides the setting mentioned by @Mike_McCune, there’s also Ignore interfaces with matching identifier (ignored_interface_identifiers). However, perhaps it’s not picking up net since it looks for networking.

6

Thanks.
I forgot to mention how my servers subscribe. I’m not using Puppet as orchestration tool, but Chef. In cookbook I install subscription-manager, katello-host-tools and katello-host-tools-tracer packages. Then Chef creates location.facts file and adds location from Chef location so server is assigned automatically proper location in Foreman on subscription. Then I use rhsm_register Chef resource which basically subscribes it with subscription-manager. So all my facts come from subscription-manager. All my servers are CentOS 7.

In settings I have:

Exclude pattern for facts stored in foreman:
[ lo, en*v*, usb*, vnet*, macvtap*, _vdsmdummy_, veth*, docker*, tap*, qbr*, qvb*, qvo*, qr-*, qg-*, vlinuxbr*, vovsbr* ]~~~
Ignore interfaces with matching identifier:
[ lo, en*v*, usb*, vnet*, macvtap*, _vdsmdummy_, veth*, docker*, tap*, qbr*, qvb*, qvo*, qr-*, qg-*, vlinuxbr*, vovsbr* ]

I’m not sure why it would use net and Foreman expects networking, unless this was changed in subscription-manager.

7

Just checked in detail and from net and most of these are duplicate:

 net::interface::br-2c6471e16e6d::ipv4_address
 net::interface::br-2c6471e16e6d::ipv4_address_list
 net::interface::br-2c6471e16e6d::ipv4_broadcast
 net::interface::br-2c6471e16e6d::ipv4_broadcast_list
 net::interface::br-2c6471e16e6d::ipv4_netmask
 net::interface::br-2c6471e16e6d::ipv4_netmask_list
 net::interface::br-2c6471e16e6d::mac_address

Except for ipv4_address the other info is really not necessary for me to have in Foreman.
Unless its som dependency that I need to have this?

8

Ah, it’s subscription manager that uses net. I assumed it was Puppet. I’ve never used subman.

9

So I’ve ran as you suggested @Mike_McCune to cleanup facts.
I’ve expanded the default exclude list the following way

Exclude pattern for facts stored in foreman:
[ lo, en*v*, usb*, vnet*, macvtap*, _vdsmdummy_, veth*, docker*, tap*, qbr*, qvb*, qvo*, qr-*, qg-*, vlinuxbr*, vovsbr*, net.interface.*.mac_address, net.interface.*.ipv4_address_list, net.interface.*.ipv4_broadcast, net.interface.*.ipv4_broadcast_list, net.interface.*.ipv4_netmask, net.interface.*.ipv4_netmask_list ]
Ignore interfaces with matching identifier:
[ lo, en*v*, usb*, vnet*, macvtap*, _vdsmdummy_, veth*, docker*, tap*, qbr*, qvb*, qvo*, qr-*, qg-*, vlinuxbr*, vovsbr*, cali* ]

After checking again, these are the new results:

 awk -F "::" '{ print $1 }' pg_fact_names.log | sort | uniq -c | sort -nr | head -n5
   5552  net
    221  mountpoints
    145  partitions
    100  dmi
     59  ec2_metadata

But for some reason there are still some facts that didn’t get cleaned although they should be caught by the filter like:

 net::interface::br-563d05c20667::ipv4_address
 net::interface::br-563d05c20667::ipv4_address_list
 net::interface::br-563d05c20667::ipv4_broadcast
 net::interface::br-563d05c20667::ipv4_broadcast_list
 net::interface::br-563d05c20667::ipv4_netmask
 net::interface::br-563d05c20667::ipv4_netmask_list
 net::interface::br-563d05c20667::mac_address
 net::interface::cali4595a5bc366
 net::interface::cali4595a5bc366::mac_address
 net::interface::calid35784f1566
 net::interface::calid35784f1566::mac_address
 net::interface::calif75fee0d848

I’m not sure why.

10

For interface exclude list you give it just interface name (identifier, like eth0 etc). In your case this would be br-* and cali* (?). This makes sure that there will be NIC created in the database with that name, this can dramatically slow down host tables.

For fact filters you want to put the whole fact separated by ::. This would be something like net::interface::br-*::ipv4_address. Do not use dots but those four-dots instead, this is our internal syntax.

Get back to us how this helped.

11

I’ve tried using 4 dots but got error syntax was wrong. So I found that it should be replaced with single dots. I’ve figured out that net facts do not play a role on server, in All Hosts page, there is still IP address, this is only thing important, so I’ve replaced those granular filter with net* and it cleaned up in database everything from net.

So I went to test and and started enrolling new machines. And again requests took too long again and filled up connections

2020-09-10T15:12:51 [F|app|694082b4]   
ActionView::Template::Error (could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use):
    15:     <%= stylesheet_link_tag 'application' %>
    16:     <%= yield(:stylesheets) %>
    17: 
    18:     <%= csrf_meta_tags %>
    19: 
    20:     <script type="text/javascript">
    21:       var URL_PREFIX = '<%= controller.relative_url_root %>';
  
lib/foreman/silenced_logger.rb:37:in `silence'
app/views/layouts/base.html.erb:18:in `_273a583cd49b9700958c0d980ddfc1d9'
app/views/layouts/application.html.erb:5:in `_4a43a2a456ac2a1b33d10b158bad7a4c'
app/controllers/application_controller.rb:352:in `generic_exception'
katello (3.16.0) lib/katello/middleware/event_daemon.rb:10:in `call'
lib/foreman/middleware/telemetry.rb:10:in `call'
lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
lib/foreman/middleware/logging_context_session.rb:22:in `call'
lib/foreman/middleware/logging_context_request.rb:11:in `call'
katello (3.16.0) lib/katello/prevent_json_parsing.rb:12:in `call'
2020-09-10T15:12:52 [I|app|4185a68d] Started POST "/api/config_reports" for 127.0.0.1 at 2020-09-10 15:12:52 +0000
2020-09-10T15:12:52 [I|app|4185a68d] Processing by Api::V2::ConfigReportsController#create as JSON
2020-09-10T15:12:52 [I|app|4185a68d]   Parameters: {"config_report"=>"[FILTERED]", "apiv"=>"v2"}
2020-09-10T15:12:52 [E|kat|9fcebb3f] ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:221:in `block in wait_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:210:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:210:in `wait_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:171:in `internal_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:297:in `internal_poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:166:in `block in poll'
/opt/rh/rh-ruby25/root/usr/share/ruby/monitor.rb:226:in `mon_synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:175:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:166:in `poll'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:875:in `acquire_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:593:in `checkout'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:437:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_adapters/abstract/connection_pool.rb:1119:in `retrieve_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_handling.rb:221:in `retrieve_connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/connection_handling.rb:189:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/delegation.rb:92:in `connection'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:1298:in `preprocess_order_args'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:364:in `order!'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/query_methods.rb:359:in `order'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:554:in `ordered_relation'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:519:in `find_nth_with_limit'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:512:in `find_nth'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/relation/finder_methods.rb:120:in `first'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/active_record/session_store/session.rb:58:in `find_by_session_id'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:124:in `block in get_session_model'
/usr/share/foreman/lib/foreman/silenced_logger.rb:37:in `silence'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:123:in `get_session_model'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-session_store-1.1.1/lib/action_dispatch/session/active_record_store.rb:140:in `find_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:314:in `load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:45:in `block in load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:53:in `stale_session_check!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/session/abstract_store.rb:45:in `load_session'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:234:in `load!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:230:in `load_for_write!'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/request/session.rb:132:in `[]='
/opt/theforeman/tfm/root/usr/share/gems/gems/gettext_i18n_rails-1.8.0/lib/gettext_i18n_rails/action_controller.rb:5:in `set_gettext_locale'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:428:in `block in make_lambda'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:200:in `block (2 levels) in halting'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:34:in `block (2 levels) in <module:Callbacks>'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:201:in `block in halting'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `block in invoke_before'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:513:in `invoke_before'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:110: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-6.0.3.1/lib/active_support/callbacks.rb:121: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-6.0.3.1/lib/active_support/callbacks.rb:121: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-6.0.3.1/lib/active_support/callbacks.rb:121: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-6.0.3.1/lib/active_support/callbacks.rb:121: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-6.0.3.1/lib/active_support/callbacks.rb:121: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-6.0.3.1/lib/active_support/callbacks.rb:121:in `block in run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:139:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/callbacks.rb:41:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/rescue.rb:22:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:33:in `block in process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `block in instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications/instrumenter.rb:24:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/notifications.rb:180:in `instrument'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/instrumentation.rb:32:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal/params_wrapper.rb:245:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/activerecord-6.0.3.1/lib/active_record/railties/controller_runtime.rb:27:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/app/controllers/katello/concerns/api/api_controller.rb:40:in `process_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/abstract_controller/base.rb:136:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionview-6.0.3.1/lib/action_view/rendering.rb:39:in `process'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:190:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_controller/metal.rb:254:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:50:in `dispatch'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:33:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:19:in `block in <class:Constraints>'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/mapper.rb:48:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:49:in `block in serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/journey/router.rb:32:in `serve'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/routing/route_set.rb:834:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/middleware/event_daemon.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-dsl-2.2.2/lib/apipie_dsl/static_dispatcher.rb:67:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/static_dispatcher.rb:66:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/extractor/recorder.rb:137:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/usr/share/foreman/lib/foreman/middleware/telemetry.rb:10:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/apipie-rails-0.5.17/lib/apipie/middleware/checksum_in_headers.rb:27:in `call'
/usr/share/foreman/lib/foreman/middleware/catch_json_parse_errors.rb:9:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/tempfile_reaper.rb:15:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/etag.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/conditional_get.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/head.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/http/content_security_policy.rb:18:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_session.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:266:in `context'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/session/abstract/id.rb:260:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/cookies.rb:648:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:27:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/callbacks.rb:101:in `run_callbacks'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/callbacks.rb:26:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/actionable_exceptions.rb:17:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/debug_exceptions.rb:32:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/show_exceptions.rb:33:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:37:in `call_app'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/rack/logger.rb:28:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/sprockets-rails-3.2.1/lib/sprockets/rails/quiet_assets.rb:13:in `call'
/usr/share/foreman/lib/foreman/middleware/logging_context_request.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/remote_ip.rb:81:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/request_id.rb:27:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/katello-3.16.0/lib/katello/prevent_json_parsing.rb:12:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/method_override.rb:24:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/runtime.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/activesupport-6.0.3.1/lib/active_support/cache/strategy/local_cache_middleware.rb:29:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/executor.rb:14:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/static.rb:126:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/sendfile.rb:110:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/actionpack-6.0.3.1/lib/action_dispatch/middleware/host_authorization.rb:76:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/secure_headers-6.3.0/lib/secure_headers/middleware.rb:11:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/engine.rb:527:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `public_send'
/opt/theforeman/tfm/root/usr/share/gems/gems/railties-6.0.3.1/lib/rails/railtie.rb:190:in `method_missing'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:74:in `block in call'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `each'
/opt/theforeman/tfm/root/usr/share/gems/gems/rack-2.2.2/lib/rack/urlmap.rb:58:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/configuration.rb:228:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:682:in `handle_request'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:472:in `process_client'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/server.rb:328:in `block in run'
/opt/theforeman/tfm/root/usr/share/gems/gems/puma-4.3.3/lib/puma/thread_pool.rb:134:in `block in spawn_thread'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-2.2.2/lib/logging/diagnostic_context.rb:474:in `block in create_with_logging_context'
2020-09-10T15:12:52 [I|app|9fcebb3f] Completed 500 Internal Server Error in 5003ms (Views: 0.3ms | ActiveRecord: 0.0ms | Allocations: 10679)
2020-09-10T15:12:52 [I|app|e3f6259e] Started GET "/rhsm/status" for 127.0.0.1 at 2020-09-10 15:12:52 +0000
2020-09-10T15:12:52 [I|app|e3f6259e] Processing by Katello::Api::Rhsm::CandlepinProxiesController#server_status as JSON
2020-09-10T15:12:53 [E|app|27970a70] ActiveRecord::ConnectionTimeoutError: could not obtain a connection from the pool within 5.000 seconds (waited 5.000 seconds); all pooled connections were in use
12

I’ve increased db pool from 5 to 10 in /etc/foreman/database.yml and restarted services to apply.
I’ll try if this works. Is there some foreman-rake command which would run db optimization or find errors if there are any?

13

Increasing pool didn’t help. :cry: Even doubling would fill it up. Returned to default 5.
The problem seems to be somewhere in DB, but I have no clue how to resolve it or what to do now.

14

I think I might be on to some bug. Since I was enrolling locations i tried the same one and as soon as add more servers the DB would fall apart. Yesterday, I removed servers from the location which I subscribed when the issues started. I added new smart proxy from a different location which has around 120 servers, all subscribed all without issues and Foreman had no performance problems, average http request response time was around 100 ms.

As soon as I try adding servers from the location that the problems started , problems start again. Remove them, no problems anymore.

The difference between locations is that the problematic one is 5 years old, and non-problematic 2 years. Older image.

I suspect there are some rhsm facts in this older image when introduced to DB cause it to start crashing.
So I need to find which facts are causing this. Any suggestions are appreciated for the easiest way to dig this info out. :slight_smile:

15

Checked differences out with:

subscription-manager facts --list

The problematic VM’s have the following facts which non-problematic don’t have.

dmi.bios.address:
dmi.connector.external_connector_type:
dmi.connector.external_reference_designator:
dmi.connector.internal_connector_type:
dmi.connector.internal_reference_designator:
dmi.connector.port_type:
proc_cpuinfo.common.apicid:
proc_cpuinfo.common.core_id:
proc_cpuinfo.common.initial_apicid:
proc_cpuinfo.common.processor:

The non-problematic have these which problematic don’t have:

dmi.bios.bios_revision:
dmi.system.family:
dmi.system.sku_number:
net.interface.docker0.ipv6_address.link:
net.interface.docker0.ipv6_address.link_list:
net.interface.docker0.ipv6_netmask.link:
net.interface.docker0.ipv6_netmask.link_list:
16

This is something we’re working on.

By default we can have 16 threads so I think that’s closer to what you need. If you need to account for every worker as well, it may be workers * threads (default 2 * 16 = 32).

This is an area that did change in 2.1 when we moved from Passenger to Puma.

1 Like
17

Thanks for the info. I’ve tried adding 16 and 32 as per your recommendation. In those cases I don’t see http responses taking too long, but it simply dies. Logs stop, everything drops dead.
Is there some other setting I should change except pool in database.yml?

18

Can you narrow it down to what HTTP requests are slow? In production.log you will find amount of miliseconds spent in each controller and action. Is that always fact upload or some other endpoint? Also how much time is spent in the DB?

19

After thinking about this for a long time, why would it not work with 4k servers when this is so small number compared to Foreman capacity it came to me that in 2.0 I applied a patch for a BUG where packages were not showing. Could not calculate errata status /no packake info/ Foreman 2.0/Katello 3.15

I presumed, with that patch and upgrade to new version something has to be broken in DB.
So I decided to cut my losses, unsubscribe all the machines, create new fresh 2.1 install and subscribe them all back.

So far I’ve subscribed 7k machines and absolutely no issues at all. I even stress tested it with running simultaneous subscription of 100 machines at a time, with 6k already registered. The highest average response time I could get it was 700 ms. When no subscribing or jobs are ran, average response is under 50 ms. Fresh install works like a charm.

We can close this. However I seem to have found a bug now regarding pulp3. Pulp 3 can't work with yum repo requiring auth/Foreman 2.1.2

2 Likes