RPG Maker VXAce Profiler

[+ Archeia 160]

RPG Maker VXAce Profiler

Introduction
Primarily a scripter's tool. It helps you check out the performance of your game and is a lot more accurate than FPS relative values.
This script is made with Neonblack
 
% time 
The percent of the time spent inside the procedure itself (not counting children). 
cumulative seconds 
The total number of seconds spent in the procedure, including children. 
self seconds 
The total number of seconds spent in the procedure itself (not counting children). 
calls 
The total number of times the procedure was called. 
self ms/call 
The average time taken by the procedure itself on each call, in ms. 
total ms/call 
The average time taken by each call to the procedure, including time spent in child functions.
 
Screenshots


How to Use
Put this script below all other scripts but above main. 
Press CTRL to print to Console the results. 
 
Warning, it starts the game slow (like 0-4 FPS even) but it's accurate in performance display.
If graphics.update is skipped it means the game has a major lagspike on normal run. 
 

module CP_Profiler
  @@stacks = {}
  @@maps = {}
  @@start = 0
  
  def self.begin
    @@stacks = {}
    @@maps = {}
    @@start = Process.times[0]
    set_trace_func proc { |event, file, line, id, binding, klass|
    case event
    when "c-call", "call"
      now = Process.times[0]
      stack = (@@stacks[Thread.current] ||= [])
      stack.push [now, 0.0]
    when "c-return", "return"
      now = Process.times[0]
      key = "#{klass}##{id}"
      stack = (@@stacks[Thread.current] ||= [])
      if tick = stack.pop
        threadmap = (@@maps[Thread.current] ||= {})
        data = (threadmap[key] ||= [0, 0.0, 0.0, key])
        data[0] += 1
        cost = now - tick[0]
        data[1] += cost
        data[2] += cost - tick[1]
        stack[-1][1] += cost if stack[-1]
      end
    end
    }
  end
  
  def self.print
    set_trace_func nil
    total = Process.times[0]
    total = 0.01 if total == 0
    totals = {}
    @@maps.values.each do |threadmap|
      threadmap.each do |key,data|
        total_data = (totals[key] ||= [0, 0.0, 0.0, key])
        total_data[0] += data[0]
        total_data[1] += data[1]
        total_data[2] += data[2]
      end
    end
    data = totals.values
    data = data.sort_by{ |x| -x[2] }
    sum = 0
    puts sprintf "     %%   cumulative   self              self     total\n"
    puts sprintf "    time   seconds   seconds    calls  ms/call  ms/call  name\n"
    for d in data
      break if d[2] <= 0.0
      sum += d[2]
      puts sprintf "%8.2f %8.2f  %8.2f %8d %8.2f %8.2f  %s\n",
          d[2]/total*100, sum, d[2], d[0], d[2]*1000/d[0], d[1]*1000/d[0], d[3]
    end
    msgbox "Results printed to console.\nTracking reset."
  end
end

class Scene_Base
  alias_method :cp_profiler_342341_update, :update
  def update(*args)
    cp_profiler_342341_update(*args)
    if Input.trigger?(:CTRL)
      CP_Profiler.print
      CP_Profiler.begin
    end
  end
end

CP_Profiler.begin

For draw in a text version instead Theo_Allen made a version over here:

module CP_Profiler
  @@stacks = {}
  @@maps = {}
  @@start = 0
  
  def self.begin
    @@stacks = {}
    @@maps = {}
    @@start = Process.times[0]
    set_trace_func proc { |event, file, line, id, binding, klass|
    case event
    when "c-call", "call"
      now = Process.times[0]
      stack = (@@stacks[Thread.current] ||= [])
      stack.push [now, 0.0]
    when "c-return", "return"
      now = Process.times[0]
      key = "#{klass}##{id}"
      stack = (@@stacks[Thread.current] ||= [])
      if tick = stack.pop
        threadmap = (@@maps[Thread.current] ||= {})
        data = (threadmap[key] ||= [0, 0.0, 0.0, key])
        data[0] += 1
        cost = now - tick[0]
        data[1] += cost
        data[2] += cost - tick[1]
        stack[-1][1] += cost if stack[-1]
      end
    end
    }
  end
  
  def self.print
    set_trace_func nil
    total = Process.times[0]
    total = 0.01 if total == 0
    totals = {}
    @@maps.values.each do |threadmap|
      threadmap.each do |key,data|
        total_data = (totals[key] ||= [0, 0.0, 0.0, key])
        total_data[0] += data[0]
        total_data[1] += data[1]
        total_data[2] += data[2]
      end
    end
    data = totals.values
    data = data.sort_by{ |x| -x[2] }
    sum = 0
    File.open('profiller.txt', 'w') do |file|
      text = sprintf "     %%   cumulative   self              self     total\n"
      file.print(text)
      text = sprintf "    time   seconds   seconds    calls  ms/call  ms/call  name\n"
      file.print(text)
      for d in data
        break if d[2] <= 0.0
        sum += d[2]
        text = sprintf "%8.2f %8.2f  %8.2f %8d %8.2f %8.2f  %s\n",
          d[2]/total*100, sum, d[2], d[0], d[2]*1000/d[0], d[1]*1000/d[0], d[3]
        file.print(text)
      end
      msgbox "Results printed to profiller.txt.\nTracking reset."
    end
  end
end

class Scene_Base
  alias_method :cp_profiler_342341_update, :update
  def update(*args)
    cp_profiler_342341_update(*args)
    if Input.trigger?(:CTRL)
      CP_Profiler.print
      CP_Profiler.begin
    end
  end
end

CP_Profiler.begin 

Edited October 16, 2014 by Archeia

[Caveras 40]

This is a nice and interesting helper script, thanks!
 

Only one thing: You mention the graphics.update skipping without providing any info as to what can cause this or how this can be changed/solved. For a regular non-scripting user, such info might be valuable =)

Edited October 17, 2014 by Caveras

[+ Archeia 160]

Since it checks the time between frames and then updates based on that; it was probably skipping frames and got knocked off.

That means that particular section of your game is lagging.

Edited October 23, 2014 by Archeia