Project

General

Profile

Bug #12359

100% cpu usage foreman-proxy after upgrade to 1.9

Added by Veaceslav Mindru about 4 years ago. Updated over 2 years ago.

Status:
Resolved
Priority:
Normal
Assignee:
-
Category:
DHCP
Target version:
-
Difficulty:
Triaged:
No
Bugzilla link:
Pull request:
Fixed in Releases:
Found in Releases:

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

Related to Smart Proxy - Feature #12370: Provide TTIN trap for stacktrace log outputClosed2015-11-02
Related to Smart Proxy - Bug #12392: 100% cpu usage on foreman-proxy DHCP callsResolved2015-11-04

History

#1 Updated by Lukas Zapletal about 4 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.

#2 Updated by Lukas Zapletal about 4 years ago

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

#3 Updated by Dominic Cleal about 4 years ago

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

#5 Updated by Alexandr Romanov about 4 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'

#6 Updated by Alexandr Romanov about 4 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'

#7 Updated by Dmitri Dolguikh over 3 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.

#8 Updated by Dominic Cleal over 3 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.

#9 Updated by Michael Moll over 2 years ago

  • Status changed from Feedback to Resolved

Also available in: Atom PDF