Class: LogReplayer::Replayer

Inherits:
Object
  • Object
show all
Defined in:
lib/log_replayer.rb

Constant Summary collapse

IP_REGEX =

Can include multiple comma (with optional spaces) ips or “unknown”

"[^-]*"
DATE_REGEX = 
"[0-9]{1,2}/[A-Z][a-z]{2}/[0-9]{4} *[0-9]{1,2}:[0-9]{2}:[0-9]{2}"
LOG_LINE_REGEX = 
/^#{IP_REGEX} - - \[(#{DATE_REGEX})\] "GET ([^"]*) HTTP\/1.[01]"/
EXCLUDE_ROUTES = 
%w{/health_check}.map { |regex| /^#{regex}/ }

Class Method Summary collapse

Instance Method Summary collapse

Constructor Details

#initialize(options) ⇒ Replayer

Returns a new instance of Replayer.



30
31
32
33
34
35
36
37
 
# File 'lib/log_replayer.rb', line 30

def initialize(options)
  @host = options[:host]
  @concurrency = options[:concurrency]
  @speed = options[:speed]
  @csv_output = options[:csv_output]
  @summary_output = options[:summary_output]
  @profiler = options[:profiler]
end

Class Method Details

.execute ⇒ Object 



144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
 
# File 'lib/log_replayer.rb', line 144

def self.execute
  options = Trollop::options do
    banner "Usage: #{$0} [options] sas_log_file"
    opt :host, "Host to run load test against", :type => :string, :default => "localhost:4567"
    opt :concurrency, "Client-side concurrency; maximum number of simultaneous requests", :type => :int,
                      :default => 40
    opt :speed, "Multiple of real-time to play back requests", :type => :float, :default => 1.0
    opt :csv_output, "File to output CSV data to", :type => :string
    opt :summary_output, "File to output summary data to", :type => :string
    opt :force, "Overwrite existing output file"
    opt :profiler, "trigger ruby prof"
  end
  if options[:csv_output] && File.exists?(options[:csv_output]) && !options[:force]
    STDERR.puts "Cowardly refusing to overwrite existing file '#{options[:csv_output]}'.  " +
                "Use --force to provide extra bravery."
    exit 1
  end
  Trollop::die "missing log file" unless ARGV[0]
  load_tester = self.new(options)
  load_tester.load_request_routes(ARGV[0])
  load_tester.replay_requests
end

Instance Method Details

#additional_summary ⇒ Object

returns string with additional string for the summary, override for different statusz implementations



61
62
63
64
 
# File 'lib/log_replayer.rb', line 61

def additional_summary
  statusz = EM::HttpRequest.new("http://#{@host}/statusz").get
  [/Branch.*/, /Ruby Version.*/].map {|x| x.match(statusz.response)}.compact.join(" -- ")
end

#load_request_routes(file_name) ⇒ Object 



39
40
41
42
43
44
45
46
47
48
 
# File 'lib/log_replayer.rb', line 39

def load_request_routes(file_name)
  @requests = []
  File.open(file_name) do |log_file|
    log_file.each_line do |log_line|
      @requests << parse_requests(log_line)
    end
  end
  @requests.compact!
  puts @requests.length
end

#parse_requests(log_line) ⇒ Object

returns hash of { :time, :route, :action, :request_options } override this in subclass to work support different log formats



52
53
54
55
56
57
58
 
# File 'lib/log_replayer.rb', line 52

def parse_requests(log_line)
  match = log_line.match(LOG_LINE_REGEX)
  return nil unless match
  date, route = match[1..2]
  return nil if EXCLUDE_ROUTES.any? { |exclude| route.match(exclude) }
  { :time => Time.parse(date), :route => route, :action => :get, :request_options => {} }
end

#replay_requests ⇒ Object

Replay logs in (a multiple of) real time



67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
 
# File 'lib/log_replayer.rb', line 67

def replay_requests
  log_start_time = @requests[0][:time]
  replay_start_time = Time.now
  count = 0
  csv_file = File.open(@csv_output, "w") if @csv_output
  csv_file.puts "id,status,processing time,start delay" if @csv_output

  error_count = 0
  status_counts = Hash.new(0)
  total_time = 0
  max_request_processing_time = 0
  min_request_processing_time = nil
  app_build = nil
  ruby_version = nil
  summary_header = ''
  EM.synchrony do
    # __start__ and __stop__ are for rack-perftools_profiler.
    EventMachine::HttpRequest.new("http://#{@host}/__start__").get if @profiler
    EM::Synchrony::FiberIterator.new(@requests, @concurrency).each do |request|
      next unless [:get, :post, :patch, :put, :delete].include? request[:action]
      # Track which request this is.  Note that count is shared between fibers, so will likely be changed by
      # another fiber before it's used.  So store it in the block-local mycount.
      count += 1
      mycount = count

      # Figure out when the request should start, and sleep until then
      request_offset = request[:time] - log_start_time
      replay_time = replay_start_time + request_offset / @speed
      sleep_time = replay_time - Time.now
      EM::Synchrony.sleep(sleep_time) if sleep_time > 0

      # Send the request, and track how long it takes to complete
      url = "http://#{@host}#{request[:route]}"
      request_start_time = Time.now
      client = EventMachine::HttpRequest.new(url, :connect_timeout => 15, :inactivity_timeout => 60)
      response = client.public_send(request[:action], request[:request_options])

      request_processing_time = Time.now - request_start_time
      if (request_processing_time > max_request_processing_time)
        max_request_processing_time = request_processing_time
      end
      if min_request_processing_time.nil? || min_request_processing_time > request_processing_time
        min_request_processing_time = request_processing_time
      end
      status = response.response_header.http_status

      if csv_file
        csv_file.puts "#{mycount},#{status},#{request_processing_time},#{request_start_time - replay_time}"
      end
      total_time += request_processing_time
      status_counts[status] += 1
      error_count += 1 if response.error
      STDERR.puts "#{mycount}: Error: #{response.error}" if response.error
      unless status == 200
        STDERR.puts "#{mycount}: received status code: #{status}, body: #{response.response}"
      end
    end
    EventMachine::HttpRequest.new("http://#{@host}/__stop__").get if @profiler
    summary_header = additional_summary
    EventMachine.stop
  end
  csv_file.close if csv_file
  if @summary_output
    File.open(@summary_output, "w") do |summary|
      summary.puts summary_header
      summary.puts "Log File: #{ARGV[0]}"
      summary.puts "Speed: #{@speed}"
      summary.puts "Concurrency: #{@concurrency}"
      summary.puts "Average request time,#{total_time/count}"
      summary.puts "Max request time,#{max_request_processing_time}"
      summary.puts "Min request time,#{min_request_processing_time}"
      summary.puts "Errors,#{error_count}"
      status_counts.each { |status, count| summary.puts "Status #{status},#{count}" }
    end
  end
end