procalyzer - analyze proc frequency from WoW combat log (See related posts)

# Usage:
# File.open('Logs/WowCombatLog.txt') {|log| 
#    Procalyzer::procalyze(log,"Light's Ward",&Procalyzer::PLAYER_SWING_OR_SPELL).dump
# }

require 'time'
require 'csv'

Stats = Struct.new(:min,:max,:n,:sx,:sx2)

# calculate mean, stdev, etc for an array of numbers
class Stats 
  def initialize(population)
    self.n = 0
    self.sx = self.sx2 = 0.0
    population.each { |x|
      self.n += 1
      self.sx += x
      self.sx2 += x*x;
      self.min = x if self.min.nil? or x < self.min
      self.max = x if self.max.nil? or x > self.max
    }
  end

  def mean
    sx/n
  end
  
  def variance
    sx2/n - (sx/n)**2
  end
 
  def stdev
    variance ** 0.5
  end

  def to_s
    "#{mean} (dev: #{stdev}, range: #{min} - #{max}, n: #{n})"
  end
end

module Procalyzer
	# wow 2.4 log entry
	LogEntry = Struct.new(:time,:message,:actor_guid,:actor_name,:actor_id,:target_guid,:target_name,:target_id,:rest)

	# parse a log into a list of LogEntries.
	# if block given, yields each entry and returns a list of the result
	# else resturns a list of entries
	def self.parse_log(stream) 
		lines = []
		while line=stream.gets
			entry = LogEntry.new
			line =~ %r{^(\d+)/(\d+) (\d\d):(\d\d):(\d\d).(\d\d\d) (.*)$} or raise "Couldnt parse line: #{line}"
			entry.time = Time.local(Time.new.year, $1.to_i, $2.to_i, $3.to_i, $4.to_i, $5.to_i, 1000*$6.to_i)
			entry.message, 
				entry.actor_guid, entry.actor_name, entry.actor_id, 
				entry.target_guid, entry.target_name, entry.target_id, 
				*rest = *CSV.parse_line($7.strip)
			entry.rest = rest
			if block_given?
				lines << yield(entry)
			else
				lines << entry
			end
		end
		lines
	end

	# Scans a logfile, runs event handlers for events matching certain filters
	class EventScanner
		def initialize
			@filters = []
			@start = []
			@end = []
		end
	
		# add a handler to be run for events matching filter
		def on(filter, &block)
			@filters << [filter,block]
		end
		# add a handler at the start
		def start(&block)
			@start << block
		end
		# add a handler at the end
		def end(&block)
			@end << block
		end
	
		# scan the stream and run handlers
		def run(file) 
			@start.each {|s| s.call() }
			Procalyzer::parse_log(file) {|entry|
				@filters.each {|filter,block|
					block.call(entry) if filter[entry]
				}
			}
			@end.each {|s| s.call() }
		end
	end

	# Container for analysis results
	# durations is a list of the proc lengths found
	# intervals is the list of times from one proc to the next
	# cooldown is the estimated or specified internal cooldown
	# procs is a list of 1 or 0 entries specifying whether each eligible event procced the aura
	ProcResults = Struct.new(:durations, :intervals, :cooldown, :procs)
	class ProcResults
		def initialize
			self.durations=[]
			self.intervals=[]
			self.procs=[]
		end
		# print results in a pretty human readable form
		def dump(out=$stdout)
			if self.durations.empty?
				out.puts "Proc did not occur."
			elsif self.intervals.empty?
				out.puts "Proc occurred once only."
			else
				dur_stats = Stats.new(durations)
				out.puts "Duration: #{dur_stats}"
				if dur_stats.stdev/dur_stats.mean > 0.1
					out.puts "Standard deviation of duration is more than 10%."
					out.puts "This can indicate a proc with no cooldown that refreshes itself."
				end
				interval_stats = Stats.new(intervals)
				out.puts "Interval: #{interval_stats}"
				out.printf("Uptime: %.2f%%\n", 100.0*(dur_stats.sx - durations[-1])/interval_stats.sx)
				out.puts "Internal cooldown: #{cooldown}"
				proc_stats = Stats.new(procs)			
				out.printf("Proc chance: %.2f%% (%d/%d)\n", 100*proc_stats.mean, proc_stats.sx.to_i, proc_stats.n)
			end
		end
	end

	# Analyse a log file, looking for a self-buff triggered by an event.
	# Assume it has a fixed % to proc unless it is on cooldown (or already active, 
	# in which case it could theoretically proc but won't slow in the log)
	# we do this in two phases:
	# 1) measure proc durations and intervals, and estimate cooldown if it's not specified
	#    (just minimum interval rounded down to nearest second)
	# 2) count eligible proccing events (ones outside cooldown) and see which procced it
	# file is a seekable stream containing the log
	# auraname is the buff name like "Haste"
	# cooldown is the internal cooldown if known (else will be estimated)
	# proc_trigger is a filter block for proc events (takes an event, returns true if the event can proc
	#   the aura, assuming the aura isnt on cooldown or already up)
	# returns a procresults object
	def self.procalyze(file, auraname, cooldown=nil, &proc_trigger) 
		results = ProcResults.new
		results.cooldown=cooldown

		scanner = EventScanner.new
	
		start = nil
		last = nil
	
		# Aura start: record start time and interval
		scanner.on(proc {|e| e.message == "SPELL_AURA_APPLIED" and e.rest[1] == auraname} ) {|evt|
			start = evt.time.to_f
			results.intervals << (start-last) if last
			last = start
		}
		# Aura finish: record duration
		scanner.on(proc {|e| e.message == "SPELL_AURA_REMOVED" and e.rest[1] == auraname} ) {|evt|
			if start
				duration = evt.time.to_f - start
				results.durations << duration
			end
		}
		scanner.run(file)

		return results if results.intervals.length==0

		# Estimate cooldown if not given	
		if results.cooldown.nil?
			interval_stats = Stats.new(results.intervals)
			duration_stats = Stats.new(results.durations)
			if(duration_stats.stdev/duration_stats.mean > 0.1)
				results.cooldown = 0.0
			else
				results.cooldown = interval_stats.min.floor
			end
			puts "Using cooldown = #{results.cooldown}" if $DEBUG
		end
	
		file.pos = 0 # restart file
		last_swing_time = nil
		last_swing_could_proc = false
		aura_up = false
		start = nil
		scanner = EventScanner.new

		start_swing = proc{|evt| last_swing_time = evt.time.to_f; last_swing_count_proc = true  }
		end_swing = proc{
			if(last_swing_could_proc)
				puts "Possible proc: #{last_swing_time}" if $DEBUG
				results.procs << (aura_up ? 1 : 0)
			end
			last_swing_could_proc = false
			last_swing_time = nil
		}

		# Aura start, start cooldown timer and set aura_up
		scanner.on(proc {|e| e.message == "SPELL_AURA_APPLIED" and e.rest[1] == auraname} ) {|evt|
			puts "Aura start: #{evt.time.to_f}" if $DEBUG
			start = evt.time.to_f
			aura_up = true
			end_swing.call()
		}
		# Aura end, clear aura_up
		scanner.on(proc {|e| e.message == "SPELL_AURA_REMOVED" and e.rest[1] == auraname} ) {|evt|
			aura_up = false
		}
		# Proc trigger event - eg a melee swing
		scanner.on(proc_trigger) {|evt|
			# first, this is the point where we confirm the previous swing didnt proc the aura
			end_swing.call()

			# record details of this swing, incl whether it could proc
			time_since_last = (start.nil?) ? 99999.0 : (evt.time.to_f - start)
			last_swing_could_proc = (not aura_up) && (time_since_last > results.cooldown)
			last_swing_time = evt.time.to_f
		}
		# at the end of the log file, confirm that the last swing didnt proc the aura
		scanner.end(&end_swing) 

		scanner.run(file)
		results
	end

	# actor_id for the player
	PLAYER_ID = "0x511"

	# predefined filters for common procs
	PLAYER_SWING = proc{|evt| evt.actor_id == PLAYER_ID and evt.message="SWING_DAMAGE" }
	PLAYER_SWING_OR_SPELL = proc{|evt| evt.actor_id == PLAYER_ID and (evt.message=="SWING_DAMAGE" or evt.message=="SPELL_DAMAGE") }
	PLAYER_SPELL_DAMAGE = proc{|evt| evt.actor_id == PLAYER_ID and evt.message=="SPELL_DAMAGE" }
        PLAYER_RANGED_OR_SPELL = proc{|evt| evt.actor_id == PLAYER_ID and (evt.message=="RANGE_DAMAGE" or evt.message=="SPELL_DAMAGE") }
end