#---------------------------------------------------------------# # # # (C) Copyright Rubysophic Inc. 2007-2008 # # All rights reserved. # # # # Use, duplication or disclosure of the code is not permitted # # unless licensed. # # # # Last Updated: 7/09/08 # #---------------------------------------------------------------# # # # RubyRunMonitor__ is responsible for keeping track of # # the response time of a Rails Request and its decomposition. # # # # For instance, a typical WEBrick/RAILS servlet dispatch # # response time components generally break down look roughly # # like this: # # # # SVS DI ACT DB DB DB VI VI # # -+-----+----+----+--+--+--+--+--+----+--+----+-+--+---+----+ # # DB' DB' DB' ACT' VI' VI' DI' SVS'# # Legend: # # SVS = DispatchServlet.service # # DI = DispatchServlet.handle_dispatch # # ACT = controller.action # # DB = ActiveRecord::ConnectionAdapters::*Adapter.execute # # VI = ActionView.Base:render_template # # All apostrophe means "end of event" # # # # Notes: # # 1. mutex held from SVS to SVS' # # 2. Total dispatch time with mutex = SVS' - SVS # # 3. Total DBIO time = Sum(DB' - DB) # # 4. Action Time = ACT' - ACT # # 5. View time = Sum(VI' - VI) # # 6. View rendering includes template + layout # # # # Another key function is to act as a command agent, responding# # to command such as displaying thread status, terminating # # threads with stack tracke and showing object heap info. # # # #---------------------------------------------------------------# module RubyRunMonitor__ require 'rubyrun_globals' require 'rubyrun_utils__' require 'rubyrun_tracer__' require 'rubyrun_rss__' require 'rubyrun_buffer_mgr__' require 'rubyrun_html__' require 'rubyrun_report__' require 'rubyrun_commander__' begin require 'rubyrunnative__' $rubyrun_native = true rescue Exception $rubyrun_native = false end include RubyRunGlobals include RubyRunUtils__ include RubyRunTracer__ include RubyRunBufferMgr__ include RubyRunHTML__ include RubyRunReport__ include RubyRunCommander__ # In response to the presence of a 'cmd_status', 'cmd_soft_kill', 'cmd_hard_kill' # or 'cmd_object_map' in the work directory, the monitor thread will either # display thread status, interrupt the threads in different manner, or show object instances # in memory def start_thread_monitor $rubyrun_logger.info "----- RubyRun Thread Monitor started -----" $rubyrun_monitor_thr = Thread.new { cycle = $rubyrun_report_timer / RUBYRUN_MONITOR_TIMER sleep_count = 0 loop do sleep RUBYRUN_MONITOR_TIMER $rubyrun_monitor_thr.exit if exit_monitor? Thread.new { begin sleep_count += 1 sleep_count == cycle ? (dump_reports(true); sleep_count = 0) : dump_reports dump_thread_status if thread_status? dump_object_map if object_map? kill_threads($rubyrun_monitor_thr) if soft_kill? || hard_kill? rescue Exception => e $stderr.print e.to_s + "\n" + e.backtrace.join("\n") exit(-1) end } end } end # Simulate a thread local storage by using a private hash keyed on thread id. # Key elements in the hash are, for instance: # {#{tid} => {:req=>request.object_id, :controller=>name, :action=> name, # :action_t=>t, :dbio=>t, :dispatch_t=>t, :view_t=>t, :uncaptured_t=>t, # :dispatch_wait_t=>t}} # Thread local is used to store performance metrics of a RAILS request. # When the same thread serves a different request, the current thread local # data needs to be rolled up and re-initialized. def create_thread_local(tid, request, klass, mid) return unless ($rubyrun_thread_local[tid] || is_action?(klass, mid)) $rubyrun_thread_local[tid] ||= {} init_thread_local(tid, request, klass, mid) unless $rubyrun_thread_local[tid][:req] if $rubyrun_thread_local[tid][:req] != request.object_id roll_up_metrics(tid) init_thread_local(tid, request, klass, mid) end end # Create a place holding global metrics hash for each RAILS application # controller class to accumulate performance metrics by action. # Key elements in the hash are, for instance: # {#{controller} => {#{action} => [dispatch_t, action_t, dbio_t, view_t, uncap_t, dispatch_wait_t]}} def create_metrics_hash(klass) $rubyrun_metrics_hash[klass.to_s.downcase[0..-11]] ||= {} end # Report timings to thread local after decomposing it into the right component. # For each action, there are 5 components of Response Time (RT) # :dispatch_t, :#{action}_t, :dbio_t, :view_t, :uncaptured_t def report_rails_timing(klass, mid, t2, t1, tid) t = t2 - t1 if is_in_hash?($rubyrun_adapter_hash, klass, mid) $rubyrun_thread_local[tid][:dbio_t] += t elsif is_in_hash?(RUBYRUN_VIEW_HASH, klass, mid) $rubyrun_thread_local[tid][:view_t] << t2 << t1 elsif is_in_hash?($rubyrun_outer_dispatch_hash, klass, mid) $rubyrun_thread_local[tid][:outer_dispatch_t] << t elsif is_in_hash?($rubyrun_inner_dispatch_hash, klass, mid) $rubyrun_thread_local[tid][:inner_dispatch_t] << t elsif is_rails_controller?(klass) $rubyrun_thread_local[tid][:action_t] = t $rubyrun_thread_local[tid][:scafold_style] = $rubyrun_thread_local[tid][:view_t].empty? ? true : false elsif is_in?(RUBYRUN_THREAD_END_HASH, klass, mid, 'strict') roll_up_metrics(tid, true) end end private # Roll up action metrics to controller_metrics_hash # First, roll up the pieces in thread_local # Then roll up the thread local data to the metrics global hash def roll_up_metrics(tid, thread_end=false) ($rubyrun_thread_local[tid].clear; return) if thread_local_incomplete?(tid) dbio_t = $rubyrun_thread_local[tid][:dbio_t] outer_dispatch_t = $rubyrun_thread_local[tid][:outer_dispatch_t].max inner_dispatch_t = $rubyrun_thread_local[tid][:inner_dispatch_t].max dispatch_wait_t = outer_dispatch_t - inner_dispatch_t view_t = $rubyrun_thread_local[tid][:view_t].empty? ? 0 : $rubyrun_thread_local[tid][:view_t].max - $rubyrun_thread_local[tid][:view_t].min action_t = ($rubyrun_thread_local[tid][:action_t]) uncap_t = $rubyrun_thread_local[tid][:scafold_style] ? outer_dispatch_t - view_t - action_t - dispatch_wait_t : outer_dispatch_t - action_t - dispatch_wait_t $rubyrun_thread_local[tid][:uncaptured_t] = uncap_t $rubyrun_thread_local[tid][:dispatch_wait_t] = dispatch_wait_t push_current_buffer([tid, Time.now, $rubyrun_thread_local[tid][:url], $rubyrun_thread_local[tid][:controller], $rubyrun_thread_local[tid][:action], outer_dispatch_t, action_t, dbio_t, view_t, uncap_t, dispatch_wait_t]) !thread_end ? $rubyrun_thread_local[tid].clear : $rubyrun_thread_local.delete(tid) end # Initialize the thread_local hash def init_thread_local(tid, request, klass, mid) $rubyrun_thread_local[tid][:req] = request.object_id $rubyrun_thread_local[tid][:controller] = klass.to_s.split('Controller')[0].downcase $rubyrun_thread_local[tid][:action] = return_method_name(mid) $rubyrun_thread_local[tid][:url] = request.protocol + request.host_with_port + request.request_uri $rubyrun_thread_local[tid][:dbio_t] = 0 $rubyrun_thread_local[tid][:outer_dispatch_t] = [] $rubyrun_thread_local[tid][:inner_dispatch_t] = [] $rubyrun_thread_local[tid][:action_t] = 0 $rubyrun_thread_local[tid][:uncaptured_t] = 0 $rubyrun_thread_local[tid][:view_t] = [] $rubyrun_thread_local[tid][:dispatch_wait_t] = 0 $rubyrun_thread_local[tid][:scafold_style] = false $rubyrun_host_with_port = request.host_with_port end # Use the data hash returned by the native function to show # the top frame inside the thread struct (node and orig_func) def get_top_stack(th_data_hash, thread_id) th_data_hash.each {|th, top_stack| if th.to_s.include?(thread_id) return "#{top_stack[0].gsub('rubyrun_', '')}" break end } end # If request aborted, thread_local can be corrupted (half filled) # Return true if corrupted else false def thread_local_incomplete? (tid) $rubyrun_thread_local[tid][:controller].nil? || $rubyrun_thread_local[tid][:action].nil? || $rubyrun_thread_local[tid][:outer_dispatch_t].empty? || $rubyrun_thread_local[tid][:inner_dispatch_t].empty? end # Sort $rubyrun_metrics_hash by response time in descending order # An array of the following data structure is returned: # metrics[0] controller/action name # metrics[1] Array of performance data # metrics[1][0] resposne time metrics[1][1] action time # metrics[1][2] database IO time metrics[1][3] view time # metrics[1][4] uncaptured time metrics[1][5] wait time # metrics[1][6] request count def sort_performance_metrics results = Hash.new $rubyrun_metrics_hash.each {|controller, action_metrics| next if action_metrics.empty? action_metrics.each {|action, metrics| results["#{controller}/#{action}"] = metrics } } results.sort {|a, b| -1*(a[1]<=>b[1])} end # An optimized runtime version of the original is_in? in RubyRunInstrumentor__ # This is used during runtime and not instrumentation, hence something of better # performance but less general is required. def is_in_hash?(hash, klass, mid) return false if hash.empty? name = klass.to_s if hash.has_key?(name) return true if hash[name].empty? method_name = return_method_name(mid) hash[name].each {|meth_name| return true if method_name.downcase == meth_name.downcase } end false end end