Bug #12359: 100% cpu usage foreman-proxy after upgrade to 1.9 - Smart Proxy - Foreman

Actions

Copy link

Bug #12359

closed

100% cpu usage foreman-proxy after upgrade to 1.9

Added by Veaceslav Mindru about 9 years ago. Updated over 7 years ago.

Status:

Resolved

Priority:

Normal

Assignee:

Category:

DHCP

Target version:

Difficulty:

Triaged:

Bugzilla link:

Pull request:

Fixed in Releases:

Found in Releases:

Foreman - 1.9.2

Red Hat JIRA:

Description

after upgrade from 1.8 to 1.9 at some point the ruby process of foreman-proxy starts consuming high amounts of mem and is on 100% cpu usage. upgrade of foreman-proxy to 1.10 did not solve the issue.

Related issues 2 (0 open — 2 closed)

Actions

Copy link

Updated by Lukas Zapletal about 9 years ago

Priority changed from High to Normal

Are you able to acquire stacktrace? Proxy does not provide signal trap, but if you modify launcher.rb with this code:

trap('TTIN') do
  puts "Starting thread dump for current Ruby process" 
  puts "=============================================" 
  puts "" 
  Thread.list.each do |thread|
    puts "Thread TID-#{thread.object_id}" 
    puts thread.backtrace
    puts "" 
  end
end

You can then send this signal and find the stracktraces in logs. Do this while CPU load is high tho.

Actions

Copy link

Updated by Lukas Zapletal about 9 years ago

Related to Feature #12370: Provide TTIN trap for stacktrace log output added

Actions

Copy link

Updated by Dominic Cleal about 9 years ago

Related to Bug #12392: 100% cpu usage on foreman-proxy DHCP calls added

Actions

Copy link

Updated by Dominic Cleal about 9 years ago

https://github.com/theforeman/smart-proxy/compare/theforeman:1.9-stable...domcleal:1.9-stable-ttin.patch - equivalent patch for 1.9.

Actions

Copy link

Updated by Alexandr Romanov about 9 years ago

This is the log form different foreman-proxy
Ubuntu 14.04
foreman-proxy 1.9.2-1

Starting thread dump for current Ruby process                                                                                                                                [54/424]
=============================================

Thread TID-5466100
/usr/share/foreman-proxy/lib/smart_proxy.rb:151:in `block (2 levels) in launch'
/usr/share/foreman-proxy/lib/smart_proxy.rb:149:in `each'
/usr/share/foreman-proxy/lib/smart_proxy.rb:149:in `block in launch'
/usr/share/foreman-proxy/lib/smart_proxy.rb:156:in `call'
/usr/share/foreman-proxy/lib/smart_proxy.rb:156:in `join'
/usr/share/foreman-proxy/lib/smart_proxy.rb:156:in `launch'
/usr/share/foreman-proxy/bin/smart-proxy:6:in `<main>'

Thread TID-20463920
/usr/lib/ruby/1.9.1/webrick/server.rb:98:in `block in start'
/usr/lib/ruby/1.9.1/webrick/server.rb:22:in `start'
/usr/lib/ruby/1.9.1/webrick/server.rb:89:in `start'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:14:in `run'
/usr/lib/ruby/vendor_ruby/rack/server.rb:264:in `start'
/usr/share/foreman-proxy/lib/smart_proxy.rb:137:in `block in launch'

Thread TID-10371020
/usr/lib/ruby/1.9.1/webrick/utils.rb:184:in `block in initialize'

Thread TID-20459720                                                                                                                                                          [31/424]
/usr/lib/ruby/1.9.1/ipaddr.rb:405:in `mask!'
/usr/lib/ruby/1.9.1/ipaddr.rb:488:in `initialize'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:32:in `new'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:32:in `include?'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:113:in `block in loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:98:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:65:in `load'
/usr/share/foreman-proxy/modules/dhcp/subnet.rb:75:in `records'
/usr/share/foreman-proxy/modules/dhcp/server.rb:79:in `block in find_record'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `each'
/usr/share/foreman-proxy/modules/dhcp/server.rb:78:in `find_record'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:84:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:35:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/nulllogger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Actions

Copy link

Updated by Alexandr Romanov about 9 years ago

And this is the log from the original installation (from which ticket was created).
Ubuntu 14.04
foreman-proxy 1.10.0~rc2-1

Starting thread dump for current Ruby process                                                                                                                               [108/564]
=============================================

Thread TID-14067700
/usr/share/foreman-proxy/lib/launcher.rb:129:in `block (2 levels) in launch'
/usr/share/foreman-proxy/lib/launcher.rb:127:in `each'
/usr/share/foreman-proxy/lib/launcher.rb:127:in `block in launch'
/usr/share/foreman-proxy/lib/launcher.rb:138:in `call'
/usr/share/foreman-proxy/lib/launcher.rb:138:in `join'
/usr/share/foreman-proxy/lib/launcher.rb:138:in `launch'
/usr/share/foreman-proxy/bin/smart-proxy:6:in `<main>'

Thread TID-27919840
/usr/lib/ruby/1.9.1/webrick/server.rb:98:in `block in start'
/usr/lib/ruby/1.9.1/webrick/server.rb:22:in `start'
/usr/lib/ruby/1.9.1/webrick/server.rb:89:in `start'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:14:in `run'
/usr/lib/ruby/vendor_ruby/rack/server.rb:264:in `start'
/usr/share/foreman-proxy/lib/launcher.rb:113:in `block in launch'

Thread TID-24946400
/usr/lib/ruby/1.9.1/webrick/utils.rb:184:in `block in initialize'

Thread TID-23493380                                                                                                                                                          [85/564]
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:96:in `block (2 levels) in parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:95:in `each'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:95:in `block in parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:90:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:90:in `parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:58:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/nulllogger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Thread TID-70174802568480                                                                                                                                                    [25/564]
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:208:in `parse_record_options'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:96:in `block (2 levels) in parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:95:in `each'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:95:in `block in parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:90:in `scan'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:90:in `parse_config_and_leases_for_records'
/usr/share/foreman-proxy/modules/dhcp/providers/server/isc.rb:147:in `loadSubnetData'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:42:in `load_subnet_data'
/usr/share/foreman-proxy/modules/dhcp/dhcp_api.rb:95:in `block in <class:DhcpApi>'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1541:in `block in compile!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `[]'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (3 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:966:in `route_eval'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:950:in `block (2 levels) in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:987:in `block in process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:985:in `process_route'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:948:in `block in route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `each'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:947:in `route!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1059:in `block in dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1056:in `dispatch!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `block in call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `block in invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `catch'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1041:in `invoke'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:882:in `call!'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:870:in `call'
/usr/lib/ruby/vendor_ruby/rack/methodoverride.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/rack/commonlogger.rb:33:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:212:in `call'
/usr/share/foreman-proxy/lib/proxy/log.rb:58:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/xss_header.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/path_traversal.rb:16:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/json_csrf.rb:18:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/base.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/protection/frame_options.rb:31:in `call'
/usr/lib/ruby/vendor_ruby/rack/nulllogger.rb:9:in `call'
/usr/lib/ruby/vendor_ruby/rack/head.rb:11:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/showexceptions.rb:21:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:175:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1949:in `call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `block in call'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1726:in `synchronize'
/usr/lib/ruby/vendor_ruby/sinatra/base.rb:1449:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:65:in `block in call'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `each'
/usr/lib/ruby/vendor_ruby/rack/urlmap.rb:50:in `call'
/usr/lib/ruby/vendor_ruby/rack/builder.rb:138:in `call'
/usr/lib/ruby/vendor_ruby/rack/handler/webrick.rb:60:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:138:in `service'
/usr/lib/ruby/1.9.1/webrick/httpserver.rb:94:in `run'
/usr/lib/ruby/1.9.1/webrick/server.rb:191:in `block in start_thread'

Actions

Copy link

Updated by Anonymous over 8 years ago

I opened a pull request (https://github.com/theforeman/smart-proxy/pull/409) that eliminates parsing of the dhcpd leases file on every request. The changes have been tested against a fairly low-load dhcpd server, and I would appreciate if you could run a test against a busy dhcpd server and report your findings in the main ticket: http://projects.theforeman.org/issues/2687.

Actions

Copy link

Updated by Dominic Cleal over 8 years ago

Category set to DHCP
Status changed from New to Feedback

The inotify-related changes from ticket #2687 have now been made in develop (nightly) for 1.13, which should drastically reduce the amount of re-parsing of config/lease files during smart proxy requests. I'm moving this ticket state to feedback as hopefully the next release will resolve this issue.

#12425 in 1.12 should also have reduced the number of calls being made to the DHCP smart proxy, thus reducing the load.

Actions

Copy link

Updated by Anonymous over 7 years ago

Status changed from Feedback to Resolved

Actions

Copy link

Also available in: Atom PDF

	Related to Smart Proxy - Feature #12370: Provide TTIN trap for stacktrace log output	Closed	Lukas Zapletal	11/02/2015			Actions
	Related to Smart Proxy - Bug #12392: 100% cpu usage on foreman-proxy DHCP calls	Resolved		11/04/2015			Actions

Project

General

Profile

Foreman » Smart Proxy

Custom queries

Bug #12359

100% cpu usage foreman-proxy after upgrade to 1.9

Updated by Lukas Zapletal about 9 years ago

Updated by Lukas Zapletal about 9 years ago

Updated by Dominic Cleal about 9 years ago

Updated by Dominic Cleal about 9 years ago

Updated by Alexandr Romanov about 9 years ago

Updated by Alexandr Romanov about 9 years ago

Updated by Anonymous over 8 years ago

Updated by Dominic Cleal over 8 years ago

Updated by Anonymous over 7 years ago