base/instrumentation.lua

   1 --[[
   2   Instrumentation Functions
   3
   4   Copyright (c) 2007 Brett Lajzer
   5
   6   See LICENSE for license information.
   7
   8 This is code to do instrumentation and profiling.
   9  Call 'instr_begin' to start instrumentation, passing an identifier string
  10  Call 'instr_end' to stop instrumentation, passing the same identifier
  11  Call 'instr_track' where the first argument is an id and the second a value
  12     to track the value of a variable across a number of arbitrary samples
  13  'instr_stats' outputs gathered information to stdout.
  14
  15  For example:
  16    instr_begin("sin")
  17    sin(x)
  18    instr_end("sin")
  19 --]]
  20
  21 --keep vars in a local environment for cleanliness
  22 do
  23   local event_log = {}
  24   local run_time = {}
  25   local temp_time = {}
  26   local call_count = {}
  27   local var_track = {}
  28   local temp_start = get_ticks()
  29
  30   --starts instrumentation for an id
  31   function instr_begin(id)
  32     --check to see that we're not trying to nest these calls
  33     --and throw an error if we are
  34     if temp_time[id] ~= nil then
  35       error("ERROR: Attempt to nest instrumentations for same id: "..id)
  36     end
  37
  38     --increment call counter
  39     if call_count[id] then
  40       call_count[id] = call_count[id] + 1
  41     else
  42       call_count[id] = 1
  43     end
  44
  45     --store current time in ms
  46     temp_time[id] = get_ticks()
  47   end
  48
  49
  50   --end instrumentation for an id
  51   function instr_end(id)
  52     --check to make sure we're ending a running instrumentation
  53     -- throw an error if not.
  54     if temp_time[id] == nil then
  55       error("ERROR: Can't end instrumentation on id: "..id..". Instrumentation not started.",2)
  56     end
  57
  58     --add current time delta to total for id
  59     if run_time[id] then
  60       run_time[id] = run_time[id] + (get_ticks() - temp_time[id])
  61     else
  62       run_time[id] = get_ticks() - temp_time[id]
  63     end
  64
  65     --delete temp entry to enable error detection
  66     temp_time[id] = nil
  67   end
  68
  69
  70   --track the value of a variable
  71   function instr_track(id, val)
  72     if var_track[id] == nil then
  73       var_track[id] = {}
  74     end
  75     local pos = #var_track[id]+1
  76     var_track[id][pos] = val
  77   end
  78
  79
  80   --prints out statistics for all ids
  81   -- TODO: make printout of tracked values do min/max
  82   function instr_stats()
  83     local total_time = get_ticks() - temp_start
  84
  85     --print statistics
  86     print(string.char(27).."[1;38;40m\nCALL STATISTICS")
  87     print("==============="..string.char(27).."[0;38;40m")
  88     for k,v in pairs(call_count) do
  89       print(string.char(27).."[1;32m"..k..string.char(27).."[0;38;40m")
  90       print("\tCalls: "..v)
  91       print("\tAvg: "..string.format("%3.4f",(run_time[k] or 1)/v))
  92       print("\t% total: "..string.format("%3.4f",(run_time[k] or 1)/total_time))
  93     end
  94
  95     --variable statistics
  96     print(string.char(27).."[1;38;40m\nVAR STATISTICS")
  97     print("=============="..string.char(27).."[0;38;40m")
  98     for k,v in pairs(var_track) do
  99       local sum = 0
 100       for i,j in pairs(v) do
 101         sum = sum + j
 102       end
 103       print(string.char(27).."[1;32m"..k..string.char(27).."[0;38;40m: "..string.format("%3.4f",sum/#v))
 104     end
 105     print("")
 106
 107     --issue warnings about unended instrumentation runs
 108     local unended = false
 109     for k,v in pairs(temp_time) do
 110       print(string.char(27).."[1;31mWARNING:"..string.char(27).."[0;38;40m Unended instrumentation: "..k)
 111       unended = true
 112     end
 113
 114     --issue big warning for unended instrumentations
 115     if unended == true then
 116       print("\t*******************************************")
 117       print("\t*   There were unended instrumentations   *")
 118       print("\t*  These statistics will NOT be accurate  *")
 119       print("\t*                                         *")
 120       print("\t*  Review the above warnings and fix the  *")
 121       print("\t* related code to ensure proper profiling *")
 122       print("\t*******************************************")
 123     end
 124   end
 125
 126
 127   --log event - log stores timestamp and message, along with list of "classes"
 128   --  the classes are passed as the extra arguments to the function
 129   function instr_log(msg,...)
 130     local classes = ""
 131     if arg.n ~= 0 then
 132       for i,v in pairs(arg) do
 133         if i ~= "n" then
 134           classes = classes..v..",,"
 135         end
 136       end
 137     end
 138     event_log[#event_log+1] = {get_ticks(), classes, msg}
 139   end
 140
 141
 142   --prints out the log
 143   function instr_print_log(...)
 144         local classes = {}
 145     local class_string
 146     if arg.n == 0 then
 147       classes = {".*"}
 148       class_string = "All classes"
 149     else
 150       class_string = "Classes:"
 151       for i,v in pairs(arg) do
 152         if i ~= "n" then
 153           classes[#classes+1] = v
 154           class_string = class_string.." "..v
 155         end
 156       end
 157     end
 158
 159     --print out entires that relate to the classes specified
 160     print(string.char(27).."[1;38;40m\nEVENT LOG")
 161     print("========="..string.char(27).."[0;38;40m")
 162     print(string.char(27).."[1;32m"..class_string..string.char(27).."[0;38;40m")
 163     for k,v in pairs(event_log) do
 164       local matched = false
 165       for i,j in pairs(classes) do
 166         if string.match(v[2],j) then
 167           matched = true
 168           break
 169         end
 170       end
 171       --print out if the classes match
 172       if matched == true then
 173         print("  "..v[1]..": "..v[3])
 174       end
 175     end
 176   end
 177
 178 end