webmcp
changeset 299:47c5f33e4a6b
Trace real time and CPU time
author | jbe |
---|---|
date | Sun Mar 22 19:25:38 2015 +0100 (2015-03-22) |
parents | e0b6cb626ee6 |
children | d1d21ae9acdb |
files | framework/env/trace/__init.lua framework/env/trace/_close_section.lua framework/env/trace/_open_section.lua framework/env/trace/_render_sub_tree.lua |
line diff
1.1 --- a/framework/env/trace/__init.lua Sun Mar 22 18:58:50 2015 +0100 1.2 +++ b/framework/env/trace/__init.lua Sun Mar 22 19:25:38 2015 +0100 1.3 @@ -5,7 +5,7 @@ 1.4 if seq == 0 then 1.5 -- prepare for configuration/initialization phase 1.6 trace._disabled = false 1.7 - trace._tree = { type = "root", start_hires_time = extos.monotonic_hires_time() } 1.8 + trace._tree = { type = "root" } 1.9 trace._stack = { trace._tree } 1.10 seq = 1 1.11 elseif seq == 1 then
2.1 --- a/framework/env/trace/_close_section.lua Sun Mar 22 18:58:50 2015 +0100 2.2 +++ b/framework/env/trace/_close_section.lua Sun Mar 22 19:25:38 2015 +0100 2.3 @@ -4,8 +4,8 @@ 2.4 if not closed_section then 2.5 error("All trace sections have been closed already.") 2.6 end 2.7 - closed_section.stop_hires_time = extos.monotonic_hires_time() 2.8 - --trace.debug("END " .. extos.monotonic_hires_time() .. " / " .. os.clock()) 2.9 + closed_section.stop_real_time = extos.monotonic_hires_time() 2.10 + closed_section.stop_proc_time = os.clock() 2.11 trace._stack[pos] = nil 2.12 return closed_section 2.13 end
3.1 --- a/framework/env/trace/_open_section.lua Sun Mar 22 18:58:50 2015 +0100 3.2 +++ b/framework/env/trace/_open_section.lua Sun Mar 22 19:25:38 2015 +0100 3.3 @@ -1,8 +1,8 @@ 3.4 function trace._open_section(node) 3.5 local node = trace._new_entry(node) 3.6 node.section = true 3.7 - node.start_hires_time = extos.monotonic_hires_time() 3.8 + node.start_real_time = extos.monotonic_hires_time() 3.9 + node.start_proc_time = os.clock() 3.10 table.insert(trace._stack, node) 3.11 - --trace.debug("START " .. extos.monotonic_hires_time() .. " / " .. os.clock()) 3.12 return node 3.13 end
4.1 --- a/framework/env/trace/_render_sub_tree.lua Sun Mar 22 18:58:50 2015 +0100 4.2 +++ b/framework/env/trace/_render_sub_tree.lua Sun Mar 22 19:25:38 2015 +0100 4.3 @@ -1,5 +1,9 @@ 4.4 -local function format_time(seconds) 4.5 - return string.format("%.1f ms", seconds * 1000) 4.6 +local function format_time(real_time, proc_time) 4.7 + if proc_time then 4.8 + return string.format("%.1f ms (%.1%f ms CPU)", real_time * 1000, proc_time * 1000) 4.9 + else 4.10 + return string.format("%.1f ms", real_time * 1000) 4.11 + end 4.12 end 4.13 4.14 local function open(class) 4.15 @@ -7,36 +11,34 @@ 4.16 end 4.17 local function open_head(node) 4.18 slot.put('<div class="trace_head">') 4.19 - if node.start_hires_time and node.stop_hires_time then 4.20 - local total_duration = node.stop_hires_time - node.start_hires_time 4.21 - local child_duration = 0 4.22 + if node.start_real_time and node.stop_real_time then 4.23 + local total_real_time = node.stop_real_time - node.start_real_time 4.24 + local total_proc_time = node.stop_proc_time - node.start_proc_time 4.25 + local child_real_time = 0 4.26 + local child_proc_time = 0 4.27 for i, child in ipairs(node) do 4.28 - if child.start_hires_time and child.stop_hires_time then 4.29 - child_duration = child_duration + child.stop_hires_time - child.start_hires_time 4.30 + if child.start_real_time then 4.31 + child_real_time = child_real_time + child.stop_real_time - child.start_real_time 4.32 + child_proc_time = child_proc_time + child.stop_proc_time - child.start_proc_time 4.33 end 4.34 end 4.35 - local duration = total_duration - child_duration 4.36 - local start_text = math.floor(node.start_hires_time * 10000 + 0.5) / 10 4.37 - local total_duration_text = math.floor(total_duration * 10000 + 0.5) / 10 4.38 - local child_duration_text = math.floor(child_duration * 10000 + 0.5) / 10 4.39 - local duration_text = math.floor(duration * 10000 + 0.5) / 10 4.40 - slot.put('<div class="time">') 4.41 - slot.put('<span class="start_label">start:</span>') 4.42 - slot.put(" ") 4.43 - slot.put('<span class="start">' .. start_text .. 'ms</span>') 4.44 - slot.put(" | ") 4.45 - slot.put('<span class="duration_label">this:</span>') 4.46 - slot.put(" ") 4.47 - slot.put('<span class="duration">' .. duration_text .. 'ms</span>') 4.48 - slot.put(" | ") 4.49 - slot.put('<span class="child_duration_label">children:</span>') 4.50 - slot.put(" ") 4.51 - slot.put('<span class="child_duration">' .. child_duration_text .. 'ms</span>') 4.52 - slot.put(" | ") 4.53 - slot.put('<span class="total_duration_label">total:</span>') 4.54 - slot.put(" ") 4.55 - slot.put('<span class="total_duration">' .. total_duration_text .. 'ms</span>') 4.56 - slot.put('</div>') 4.57 + local real_time = total_real_time - child_real_time 4.58 + local proc_time = total_proc_time - child_proc_time 4.59 + slot.put( 4.60 + '<div class="time">', 4.61 + '<span class="duration_label">this:</span>', 4.62 + ' ', 4.63 + '<span class="duration">', format_time(real_time, proc_time), '</span>', 4.64 + ' | ', 4.65 + '<span class="child_duration_label">children:</span>', 4.66 + ' ', 4.67 + '<span class="child_duration">', format_time(child_real_time, child_proc_time), '</span>', 4.68 + ' | ', 4.69 + '<span class="total_duration_label">total:</span>', 4.70 + ' ', 4.71 + '<span class="total_duration">', format_time(total_real_time, total_proc_time), '</span>', 4.72 + '</div>' 4.73 + ) 4.74 end 4.75 end 4.76 local function close_head()