Skip to content

Instantly share code, notes, and snippets.

Embed
What would you like to do?
dynflow message throughput monitor
# usage
#
# 1) copy the monitory to be loaded by satellite
#
# cp dynflow_throughput_monitor.rb /usr/share/foreman/config/initializers
# service foreman-tasks restart
#
# 2) grab the collected data to be shared with engineering:
#
# tar cvf dynflow_thoughput_monitor.tar /var/log/foreman/dynflow_throughput_monitor.log*
#
# 3) remove the monitor after done collecting the data
#
# rm /usr/share/foreman/config/initializers/dynflow_throughput_monitor.rb
# service foreman-tasks restart
#
# 4) (engineering after receiving the collected tar) extract the logs:
#
# gzip -d *.gz
#
# 5) extract relevant data:
#
# * cat dynflow_thoughput_monitor.log* | sort -t';' -k2 > dynflow_throughput_monitor.csv
#
class DynflowThroughputMonitor < Dynflow::Middleware
@logger = ::Logger.new(File.join(Rails.root, 'log', 'dynflow_throughput_monitor.log'))
class << self
attr_accessor :logger
def log_header(pools)
unless @log_stats_printed
pools_columns = pools.map { |pool_name| "#{pool_name} queue_size; #{pool_name} free_workers"}.join(";")
logger.info("dynflow_throughput_monitor;_sample_time;uuid;action_class;method;event;worker;time_start;time_end;duration;#{pools_columns}")
end
@log_stats_printed = true
end
def log_stats(sample_time, uuid, action_class, method, event, worker, time_start, time_end, duration, pools_data)
pool_info = pools_data.keys.sort.map do |pool_name|
pool_data = pools_data[pool_name]
"#{pool_data[:jobs_size]};#{pool_data[:free_workers]}"
end.join(';')
logger.info("dynflow_throughput_monitor;#{sample_time};#{uuid};#{action_class};#{method};#{event};#{worker};#{time_start};#{time_end};#{duration};#{pool_info}")
end
end
def actor_context(reference)
reference.instance_variable_get('@core').instance_variable_get('@context')
end
def pools_data
executor = ForemanTasks.dynflow.world.executor
executor_core = actor_context(executor.instance_variable_get('@core'))
pools = executor_core.instance_variable_get('@pools')
unless pools
pools = {:normal => executor_core.instance_variable_get('@pool')}
end
pools.inject({}) do |hash, (pool_name, pool)|
pool = actor_context(pool)
jobs = pool.instance_variable_get('@jobs').instance_variable_get('@jobs')
free_workers = pool.instance_variable_get('@free_workers')
hash.update(pool_name => { :jobs_size => jobs.size,
:free_workers => free_workers.size })
end
end
def run(*args)
monitor_throughput('run', args.first) { pass(*args) }
end
def finalize
monitor_throughput('finalize') { pass }
end
def monitor_throughput(method, event = nil)
started_at = Time.now
pools_data = self.pools_data
uuid = "#{$$}/#{action.execution_plan_id}##{action.id}"
yield
ensure
ended_at = Time.now
self.class.log_header(pools_data.keys.sort)
self.class.log_stats(format_time(started_at), uuid, action.class, method, event.inspect, Concurrent::Actor.current.name, format_time(started_at), format_time(ended_at), '%.10f' % (ended_at - started_at), pools_data)
end
def format_time(time)
time.utc.strftime('%Y-%d-%m %H:%M:%S.%6N')
end
end
ForemanTasks.dynflow.config.on_init do |world|
world.middleware.use(DynflowThroughputMonitor)
end
@jhutar

This comment has been minimized.

Copy link

commented Apr 4, 2017

Got this error when running big ReX job. Could it be caused by this plugin?

Action:

Actions::RemoteExecution::RunHostsJob

Input:

{"job_invocation"=>
  {"id"=>22,
   "name"=>"Commands",
   "description"=>"Run subscription-manager repos --list"},
 "job_category"=>"Commands",
 "job_invocation_id"=>22,
 "current_user_id"=>3}

Output:

{}

Exception:

NoMethodError: undefined method `[]' for nil:NilClass

Backtrace:

/usr/share/foreman/config/initializers/dynflow_throughput_monitor.rb:73:in `ensure in monitor_throughput'
/usr/share/foreman/config/initializers/dynflow_throughput_monitor.rb:73:in `monitor_throughput'
/usr/share/foreman/config/initializers/dynflow_throughput_monitor.rb:58:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware/stack.rb:26:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware.rb:17:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware.rb:30:in `run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware/stack.rb:22:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/middleware/world.rb:30:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:511:in `block (2 levels) in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:510:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:510:in `block in execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:426:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:426:in `block in with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:426:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:426:in `with_error_handling'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:505:in `execute_run'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/action.rb:262:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:9:in `block (2 levels) in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract.rb:159:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract.rb:159:in `with_meta_calculation'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:8:in `block in execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:22:in `open_action'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/execution_plan/steps/abstract_flow_step.rb:7:in `execute'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/executors/parallel/worker.rb:14:in `on_message'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/context.rb:46:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/executes_context.rb:7:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/dynflow-0.8.13.3/lib/dynflow/actor.rb:26:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/awaits.rb:15:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:38:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:31:in `process_envelopes?'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/buffer.rb:20:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/termination.rb:55:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/removes_child.rb:10:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/abstract.rb:25:in `pass'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/behaviour/sets_results.rb:14:in `on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:161:in `process_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:95:in `block in on_envelope'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:118:in `block (2 levels) in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `block in synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/synchronization/mri_lockable_object.rb:38:in `synchronize'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-edge-0.2.0/lib/concurrent/actor/core.rb:115:in `block in schedule_execution'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:18:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:96:in `work'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/serialized_execution.rb:77:in `block in call_job'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:333:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:333:in `run_task'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:322:in `block (3 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:305:in `loop'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:305:in `block (2 levels) in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:304:in `catch'
/opt/theforeman/tfm/root/usr/share/gems/gems/concurrent-ruby-1.0.0/lib/concurrent/executor/ruby_thread_pool_executor.rb:304:in `block in create_worker'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `call'
/opt/theforeman/tfm/root/usr/share/gems/gems/logging-1.8.2/lib/logging/diagnostic_context.rb:323:in `block in create_with_logging_context'
@iNecas

This comment has been minimized.

Copy link
Owner Author

commented Apr 5, 2017

Thanks for info: the problem was I was testing it against non-patched version, where the code was a bit different, should work now

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
You can’t perform that action at this time.