summary refs log tree commit diff
path: root/vendor/ProFi.lua
blob: 989985f177ef5e4b065c7fbff5108453d1b1ac6e (plain)
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
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
143
144
145
146
147
148
149
150
151
152
153
154
155
156
157
158
159
160
161
162
163
164
165
166
167
168
169
170
171
172
173
174
175
176
177
178
179
180
181
182
183
184
185
186
187
188
189
190
191
192
193
194
195
196
197
198
199
200
201
202
203
204
205
206
207
208
209
210
211
212
213
214
215
216
217
218
219
220
221
222
223
224
225
226
227
228
229
230
231
232
233
234
235
236
237
238
239
240
241
242
243
244
245
246
247
248
249
250
251
252
253
254
255
256
257
258
259
260
261
262
263
264
265
266
267
268
269
270
271
272
273
274
275
276
277
278
279
280
281
282
283
284
285
286
287
288
289
290
291
292
293
294
295
296
297
298
299
300
301
302
303
304
305
306
307
308
309
310
311
312
313
314
315
316
317
318
319
320
321
322
323
324
325
326
327
328
329
330
331
332
333
334
335
336
337
338
339
340
341
342
343
344
345
346
347
348
349
350
351
352
353
354
355
356
357
358
359
360
361
362
363
364
365
366
367
368
369
370
371
372
373
374
375
376
377
378
379
380
381
382
383
384
385
386
387
388
389
390
391
392
393
394
395
396
397
398
399
400
401
402
403
404
405
406
407
408
409
410
411
412
413
414
415
416
417
418
419
420
421
422
423
424
425
426
427
428
429
430
431
432
433
434
435
436
437
438
439
440
441
442
443
444
445
446
447
448
449
450
451
452
453
454
455
456
457
--[[
ProFi v1.3, by Luke Perkin 2012. MIT Licence http://www.opensource.org/licenses/mit-license.php.
Updated to v1.4 by Robert Machmer 2017

    Example:
        ProFi = require 'ProFi'
        ProFi:start()
        some_function()
        another_function()
        coroutine.resume( some_coroutine )
        ProFi:stop()
        ProFi:writeReport( 'MyProfilingReport.txt' )

    API:
    *Arguments are specified as: type/name/default.
        ProFi:start( string/once/nil )
        ProFi:stop()
        ProFi:checkMemory( number/interval/0, string/note/'' )
        ProFi:writeReport( string/filename/'ProFi.txt' )
        ProFi:reset()
        ProFi:setHookCount( number/hookCount/0 )
        ProFi:setGetTimeMethod( function/getTimeMethod/os.clock )
        ProFi:setInspect( string/methodName, number/levels/1 )
]]

-----------------------
-- Locals:
-----------------------

local ProFi = {}
local onDebugHook, sortByDurationDesc, sortByCallCount, getTime
local DEFAULT_DEBUG_HOOK_COUNT = 0
local FORMAT_HEADER_LINE       = "| %-50s: %-40s: %-20s: %-12s: %-12s: %-12s|\n"
local FORMAT_OUTPUT_LINE       = "| %s: %-12s: %-12s: %-12s|\n"
local FORMAT_INSPECTION_LINE   = "> %s: %-12s\n"
local FORMAT_TOTALTIME_LINE    = "| TOTAL TIME = %f\n"
local FORMAT_MEMORY_LINE       = "| %-20s: %-16s: %-16s| %s\n"
local FORMAT_HIGH_MEMORY_LINE  = "H %-20s: %-16s: %-16sH %s\n"
local FORMAT_LOW_MEMORY_LINE   = "L %-20s: %-16s: %-16sL %s\n"
local FORMAT_TITLE             = "%-50.50s: %-40.40s: %-20s"
local FORMAT_LINENUM           = "%4i"
local FORMAT_TIME              = "%04.3f"
local FORMAT_RELATIVE          = "%03.2f%%"
local FORMAT_COUNT             = "%7i"
local FORMAT_KBYTES            = "%7i Kbytes"
local FORMAT_MBYTES            = "%7.1f Mbytes"
local FORMAT_MEMORY_HEADER1    = "\n=== HIGH & LOW MEMORY USAGE ===============================\n"
local FORMAT_MEMORY_HEADER2    = "=== MEMORY USAGE ==========================================\n"
local FORMAT_BANNER            = [[
###############################################################################################################
#####  ProFi, a lua profiler. This profile was generated on: %s
#####  ProFi is created by Luke Perkin 2012 under the MIT Licence, www.locofilm.co.uk
#####  Version 1.3 Original gist can be found at https://gist.github.com/perky/2838755
#####  Version 1.4 Cleaned up code to work with luacheck https://gist.github.com/rm-code/383c98a6af04652ed9f39b7ae536bcc5
###############################################################################################################


]]

-----------------------
-- Public Methods:
-----------------------

--[[
Starts profiling any method that is called between this and ProFi:stop().
Pass the parameter 'once' to so that this methodis only run once.
Example:
ProFi:start( 'once' )
]]
function ProFi:start( param )
    if param == 'once' then
        if self:shouldReturn() then
            return
        else
            self.should_run_once = true
        end
    end
    self.has_started  = true
    self.has_finished = false
    self:resetReports( self.reports )
    self:startHooks()
    self.startTime = getTime()
end

--[[
Stops profiling.
]]
function ProFi:stop()
    if self:shouldReturn() then
        return
    end
    self.stopTime = getTime()
    self:stopHooks()
    self.has_finished = true
end

function ProFi:checkMemory( ninterval, note )
    local time = getTime()
    local interval = ninterval or 0
    if self.lastCheckMemoryTime and time < self.lastCheckMemoryTime + interval then
        return
    end
    self.lastCheckMemoryTime = time
    local memoryReport = {
        ['time']   = time;
        ['memory'] = collectgarbage('count');
        ['note']   = note or '';
    }
    table.insert( self.memoryReports, memoryReport )
    self:setHighestMemoryReport( memoryReport )
    self:setLowestMemoryReport( memoryReport )
end

--[[
Writes the profile report to a file.
Param: [filename:string:optional] defaults to 'ProFi.txt' if not specified.
]]
function ProFi:writeReport( filename )
    if #self.reports > 0 or #self.memoryReports > 0 then
        filename = filename or 'ProFi.txt'
        self:sortReportsWithSortMethod( self.reports, self.sortMethod )
        self:writeReportsToFilename( filename )
        print( string.format("[ProFi]\t Report written to %s", filename) )
        return true;
    end
end

--[[
Resets any profile information stored.
]]
function ProFi:reset()
    self.reports = {}
    self.reportsByTitle = {}
    self.memoryReports  = {}
    self.highestMemoryReport = nil
    self.lowestMemoryReport  = nil
    self.has_started  = false
    self.has_finished = false
    self.should_run_once = false
    self.lastCheckMemoryTime = nil
    self.hookCount = self.hookCount or DEFAULT_DEBUG_HOOK_COUNT
    self.sortMethod = self.sortMethod or sortByDurationDesc
    self.inspect = nil
end

--[[
Set how often a hook is called.
See http://pgl.yoyo.org/luai/i/debug.sethook for information.
Param: [hookCount:number] if 0 ProFi counts every time a function is called.
if 2 ProFi counts every other 2 function calls.
]]
function ProFi:setHookCount( hookCount )
    self.hookCount = hookCount
end

--[[
Set how the report is sorted when written to file.
Param: [sortType:string] either 'duration' or 'count'.
'duration' sorts by the time a method took to run.
'count' sorts by the number of times a method was called.
]]
function ProFi:setSortMethod( sortType )
    if sortType == 'duration' then
        self.sortMethod = sortByDurationDesc
    elseif sortType == 'count' then
        self.sortMethod = sortByCallCount
    end
end

--[[
By default the getTime method is os.clock (CPU time),
If you wish to use other time methods pass it to this function.
Param: [getTimeMethod:function]
]]
function ProFi:setGetTimeMethod( getTimeMethod )
    getTime = getTimeMethod
end

--[[
Allows you to inspect a specific method.
Will write to the report a list of methods that
call this method you're inspecting, you can optionally
provide a levels parameter to traceback a number of levels.
Params: [methodName:string] the name of the method you wish to inspect.
[levels:number:optional] the amount of levels you wish to traceback, defaults to 1.
]]
function ProFi:setInspect( methodName, levels )
    if self.inspect then
        self.inspect.methodName = methodName
        self.inspect.levels = levels or 1
    else
        self.inspect = {
            ['methodName'] = methodName;
            ['levels'] = levels or 1;
        }
    end
end

-----------------------
-- Implementations methods:
-----------------------

function ProFi:shouldReturn( )
    return self.should_run_once and self.has_finished
end

function ProFi:getFuncReport( funcInfo )
    local title = self:getTitleFromFuncInfo( funcInfo )
    local funcReport = self.reportsByTitle[ title ]
    if not funcReport then
        funcReport = self:createFuncReport( funcInfo )
        self.reportsByTitle[ title ] = funcReport
        table.insert( self.reports, funcReport )
    end
    return funcReport
end

function ProFi:getTitleFromFuncInfo( funcInfo )
    local name        = funcInfo.name or 'anonymous'
    local source      = funcInfo.short_src or 'C_FUNC'
    local linedefined = funcInfo.linedefined or 0
    linedefined = string.format( FORMAT_LINENUM, linedefined )
    return string.format(FORMAT_TITLE, source, name, linedefined)
end

function ProFi:createFuncReport( funcInfo )
    local funcReport = {
        ['title']         = self:getTitleFromFuncInfo( funcInfo );
        ['count'] = 0;
        ['timer']         = 0;
    }
    return funcReport
end

function ProFi:startHooks()
    debug.sethook( onDebugHook, 'cr', self.hookCount )
end

function ProFi:stopHooks()
    debug.sethook()
end

function ProFi:sortReportsWithSortMethod( reports, sortMethod )
    if reports then
        table.sort( reports, sortMethod )
    end
end

function ProFi:writeReportsToFilename( filename )
    local file, err = io.open( filename, 'w' )
    assert( file, err )
    self:writeBannerToFile( file )
    if #self.reports > 0 then
        self:writeProfilingReportsToFile( self.reports, file )
    end
    if #self.memoryReports > 0 then
        self:writeMemoryReportsToFile( self.memoryReports, file )
    end
    file:close()
end

function ProFi:writeProfilingReportsToFile( reports, file )
    local totalTime = self.stopTime - self.startTime
    local totalTimeOutput =  string.format(FORMAT_TOTALTIME_LINE, totalTime)
    file:write( totalTimeOutput )
    local header = string.format( FORMAT_HEADER_LINE, "FILE", "FUNCTION", "LINE", "TIME", "RELATIVE", "CALLED" )
    file:write( header )
    for _, funcReport in ipairs( reports ) do
        local timer         = string.format(FORMAT_TIME, funcReport.timer)
        local count         = string.format(FORMAT_COUNT, funcReport.count)
        local relTime         = string.format(FORMAT_RELATIVE, (funcReport.timer / totalTime) * 100 )
        local outputLine    = string.format(FORMAT_OUTPUT_LINE, funcReport.title, timer, relTime, count )
        file:write( outputLine )
        if funcReport.inspections then
            self:writeInpsectionsToFile( funcReport.inspections, file )
        end
    end
end

function ProFi:writeMemoryReportsToFile( reports, file )
    file:write( FORMAT_MEMORY_HEADER1 )
    self:writeHighestMemoryReportToFile( file )
    self:writeLowestMemoryReportToFile( file )
    file:write( FORMAT_MEMORY_HEADER2 )
    for _, memoryReport in ipairs( reports ) do
        local outputLine = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_MEMORY_LINE )
        file:write( outputLine )
    end
end

function ProFi:writeHighestMemoryReportToFile( file )
    local memoryReport = self.highestMemoryReport
    local outputLine   = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_HIGH_MEMORY_LINE )
    file:write( outputLine )
end

function ProFi:writeLowestMemoryReportToFile( file )
    local memoryReport = self.lowestMemoryReport
    local outputLine   = self:formatMemoryReportWithFormatter( memoryReport, FORMAT_LOW_MEMORY_LINE )
    file:write( outputLine )
end

function ProFi:formatMemoryReportWithFormatter( memoryReport, formatter )
    local time       = string.format(FORMAT_TIME, memoryReport.time)
    local kbytes     = string.format(FORMAT_KBYTES, memoryReport.memory)
    local mbytes     = string.format(FORMAT_MBYTES, memoryReport.memory/1024)
    local outputLine = string.format(formatter, time, kbytes, mbytes, memoryReport.note)
    return outputLine
end

function ProFi:writeBannerToFile( file )
    local banner = string.format(FORMAT_BANNER, os.date())
    file:write( banner )
end

function ProFi:writeInpsectionsToFile( inspections, file )
    local inspectionsList = self:sortInspectionsIntoList( inspections )
    file:write('\n==^ INSPECT ^======================================================================================================== COUNT ===\n')
    for _, inspection in ipairs( inspectionsList ) do
        local line             = string.format(FORMAT_LINENUM, inspection.line)
        local title         = string.format(FORMAT_TITLE, inspection.source, inspection.name, line)
        local count         = string.format(FORMAT_COUNT, inspection.count)
        local outputLine    = string.format(FORMAT_INSPECTION_LINE, title, count )
        file:write( outputLine )
    end
    file:write('===============================================================================================================================\n\n')
end

function ProFi:sortInspectionsIntoList( inspections )
    local inspectionsList = {}
    for _, inspection in pairs(inspections) do
        inspectionsList[#inspectionsList+1] = inspection
    end
    table.sort( inspectionsList, sortByCallCount )
    return inspectionsList
end

function ProFi:resetReports( reports )
    for _, report in ipairs( reports ) do
        report.timer = 0
        report.count = 0
        report.inspections = nil
    end
end

function ProFi:shouldInspect( funcInfo )
    return self.inspect and self.inspect.methodName == funcInfo.name
end

function ProFi:getInspectionsFromReport( funcReport )
    local inspections = funcReport.inspections
    if not inspections then
        inspections = {}
        funcReport.inspections = inspections
    end
    return inspections
end

function ProFi:getInspectionWithKeyFromInspections( key, inspections )
    local inspection = inspections[key]
    if not inspection then
        inspection = {
            ['count']  = 0;
        }
        inspections[key] = inspection
    end
    return inspection
end

function ProFi:doInspection( inspect, funcReport )
    local inspections = self:getInspectionsFromReport( funcReport )
    local levels = 5 + inspect.levels
    local currentLevel = 5
    while currentLevel < levels do
        local funcInfo = debug.getinfo( currentLevel, 'nS' )
        if funcInfo then
            local source = funcInfo.short_src or '[C]'
            local name = funcInfo.name or 'anonymous'
            local line = funcInfo.linedefined
            local key = source..name..line
            local inspection = self:getInspectionWithKeyFromInspections( key, inspections )
            inspection.source = source
            inspection.name = name
            inspection.line = line
            inspection.count = inspection.count + 1
            currentLevel = currentLevel + 1
        else
            break
        end
    end
end

function ProFi:onFunctionCall( funcInfo )
    local funcReport = ProFi:getFuncReport( funcInfo )
    funcReport.callTime = getTime()
    funcReport.count = funcReport.count + 1
    if self:shouldInspect( funcInfo ) then
        self:doInspection( self.inspect, funcReport )
    end
end

function ProFi:onFunctionReturn( funcInfo )
    local funcReport = ProFi:getFuncReport( funcInfo )
    if funcReport.callTime then
        funcReport.timer = funcReport.timer + (getTime() - funcReport.callTime)
    end
end

function ProFi:setHighestMemoryReport( memoryReport )
    if not self.highestMemoryReport then
        self.highestMemoryReport = memoryReport
    else
        if memoryReport.memory > self.highestMemoryReport.memory then
            self.highestMemoryReport = memoryReport
        end
    end
end

function ProFi:setLowestMemoryReport( memoryReport )
    if not self.lowestMemoryReport then
        self.lowestMemoryReport = memoryReport
    else
        if memoryReport.memory < self.lowestMemoryReport.memory then
            self.lowestMemoryReport = memoryReport
        end
    end
end

-----------------------
-- Local Functions:
-----------------------

getTime = os.clock

onDebugHook = function( hookType )
    local funcInfo = debug.getinfo( 2, 'nS' )
    if hookType == "call" then
        ProFi:onFunctionCall( funcInfo )
    elseif hookType == "return" then
        ProFi:onFunctionReturn( funcInfo )
    end
end

sortByDurationDesc = function( a, b )
    return a.timer > b.timer
end

sortByCallCount = function( a, b )
    return a.count > b.count
end

-----------------------
-- Return Module:
-----------------------

ProFi:reset()
return ProFi