webmcp
changeset 115:0de41d8e2cf8
Added time protocol to trace system
author | bsw |
---|---|
date | Thu Jul 10 00:04:45 2014 +0200 (2014-07-10) |
parents | 6c4a5b136074 |
children | 30391b40722f |
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 Mon Feb 10 20:52:21 2014 +0100 1.2 +++ b/framework/env/trace/__init.lua Thu Jul 10 00:04:45 2014 +0200 1.3 @@ -1,3 +1,3 @@ 1.4 trace._disabled = false 1.5 -trace._tree = { type = "root" } 1.6 +trace._tree = { type = "root", start_hires_time = extos.monotonic_hires_time() } 1.7 trace._stack = { trace._tree }
2.1 --- a/framework/env/trace/_close_section.lua Mon Feb 10 20:52:21 2014 +0100 2.2 +++ b/framework/env/trace/_close_section.lua Thu Jul 10 00:04:45 2014 +0200 2.3 @@ -4,6 +4,7 @@ 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 trace._stack[pos] = nil 2.10 return closed_section
3.1 --- a/framework/env/trace/_open_section.lua Mon Feb 10 20:52:21 2014 +0100 3.2 +++ b/framework/env/trace/_open_section.lua Thu Jul 10 00:04:45 2014 +0200 3.3 @@ -1,6 +1,7 @@ 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 table.insert(trace._stack, node) 3.9 --trace.debug("START " .. extos.monotonic_hires_time() .. " / " .. os.clock()) 3.10 return node
4.1 --- a/framework/env/trace/_render_sub_tree.lua Mon Feb 10 20:52:21 2014 +0100 4.2 +++ b/framework/env/trace/_render_sub_tree.lua Thu Jul 10 00:04:45 2014 +0200 4.3 @@ -1,8 +1,39 @@ 4.4 local function open(class) 4.5 slot.put('<li class="trace_' .. class .. '">') 4.6 end 4.7 -local function open_head() 4.8 +local function open_head(node) 4.9 slot.put('<div class="trace_head">') 4.10 + if node.start_hires_time and node.stop_hires_time then 4.11 + local total_duration = node.stop_hires_time - node.start_hires_time 4.12 + local child_duration = 0 4.13 + for i, child in ipairs(node) do 4.14 + if child.start_hires_time and child.stop_hires_time then 4.15 + child_duration = child_duration + child.stop_hires_time - child.start_hires_time 4.16 + end 4.17 + end 4.18 + local duration = total_duration - child_duration 4.19 + local start_text = math.floor(node.start_hires_time * 10000 + 0.5) / 10 4.20 + local total_duration_text = math.floor(total_duration * 10000 + 0.5) / 10 4.21 + local child_duration_text = math.floor(child_duration * 10000 + 0.5) / 10 4.22 + local duration_text = math.floor(duration * 10000 + 0.5) / 10 4.23 + slot.put('<div class="time">') 4.24 + slot.put('<span class="start_label">start:</span>') 4.25 + slot.put(" ") 4.26 + slot.put('<span class="start">' .. start_text .. 'ms</span>') 4.27 + slot.put(" | ") 4.28 + slot.put('<span class="duration_label">this:</span>') 4.29 + slot.put(" ") 4.30 + slot.put('<span class="duration">' .. duration_text .. 'ms</span>') 4.31 + slot.put(" | ") 4.32 + slot.put('<span class="child_duration_label">children:</span>') 4.33 + slot.put(" ") 4.34 + slot.put('<span class="child_duration">' .. child_duration_text .. 'ms</span>') 4.35 + slot.put(" | ") 4.36 + slot.put('<span class="total_duration_label">total:</span>') 4.37 + slot.put(" ") 4.38 + slot.put('<span class="total_duration">' .. total_duration_text .. 'ms</span>') 4.39 + slot.put('</div>') 4.40 + end 4.41 end 4.42 local function close_head() 4.43 slot.put('</div>') 4.44 @@ -55,7 +86,7 @@ 4.45 close() 4.46 elseif node_type == "request" then 4.47 open("request") 4.48 - open_head() 4.49 + open_head(node) 4.50 slot.put("REQUESTED") 4.51 if node.view then 4.52 slot.put(" VIEW") 4.53 @@ -71,17 +102,17 @@ 4.54 close_with_children() 4.55 elseif node_type == "config" then 4.56 open("config") 4.57 - open_head() 4.58 + open_head(node) 4.59 slot.put('Configuration "', encode.html(node.name), '"') 4.60 close_with_children() 4.61 elseif node_type == "filter" then 4.62 open("filter") 4.63 - open_head() 4.64 + open_head(node) 4.65 slot.put(encode.html(node.path)) 4.66 close_with_children() 4.67 elseif node_type == "view" then 4.68 open("view") 4.69 - open_head() 4.70 + open_head(node) 4.71 slot.put( 4.72 "EXECUTE VIEW: ", 4.73 encode.html(node.module), 4.74 @@ -107,7 +138,7 @@ 4.75 else 4.76 open("action_neutral") 4.77 end 4.78 - open_head() 4.79 + open_head(node) 4.80 slot.put( 4.81 "EXECUTE ACTION: ", 4.82 encode.html(node.module), 4.83 @@ -127,17 +158,17 @@ 4.84 close() 4.85 elseif node_type == "redirect" then 4.86 open("redirect") 4.87 - open_head() 4.88 + open_head(node) 4.89 slot.put("303 REDIRECT TO VIEW: ", encode.html(node.module), "/", encode.html(node.view)) 4.90 close_with_children() 4.91 elseif node_type == "forward" then 4.92 open("forward") 4.93 - open_head() 4.94 + open_head(node) 4.95 slot.put("INTERNAL FORWARD TO VIEW: ", encode.html(node.module), "/", encode.html(node.view)) 4.96 close_with_children() 4.97 elseif node_type == "exectime" then 4.98 open("exectime") 4.99 - open_head() 4.100 + open_head(node) 4.101 slot.put( 4.102 "Finished after " .. 4.103 string.format("%.1f", extos.monotonic_hires_time() * 1000) .. 4.104 @@ -164,7 +195,7 @@ 4.105 close(); 4.106 elseif node_type == "error" then 4.107 open("error") 4.108 - open_head() 4.109 + open_head(node) 4.110 slot.put("UNEXPECTED ERROR") 4.111 close_head() 4.112 close()