webmcp
changeset 302:04b648660f9a
Time triple (cpu/db/total) for trace system
author | jbe |
---|---|
date | Sun Mar 22 20:06:26 2015 +0100 (2015-03-22) |
parents | 216cd6ca6bc8 |
children | f97e0584ec7b |
files | framework/env/trace/_new_entry.lua framework/env/trace/_open_section.lua framework/env/trace/_render_sub_tree.lua framework/env/trace/sql.lua |
line diff
1.1 --- a/framework/env/trace/_new_entry.lua Sun Mar 22 19:28:07 2015 +0100 1.2 +++ b/framework/env/trace/_new_entry.lua Sun Mar 22 20:06:26 2015 +0100 1.3 @@ -1,5 +1,7 @@ 1.4 function trace._new_entry(node) 1.5 local node = node or {} 1.6 - table.insert(trace._stack[#trace._stack], node) 1.7 + local stack = trace._stack 1.8 + local parent = stack[#stack] 1.9 + parent[#parent+1] = node 1.10 return node 1.11 end
2.1 --- a/framework/env/trace/_open_section.lua Sun Mar 22 19:28:07 2015 +0100 2.2 +++ b/framework/env/trace/_open_section.lua Sun Mar 22 20:06:26 2015 +0100 2.3 @@ -1,8 +1,10 @@ 2.4 function trace._open_section(node) 2.5 local node = trace._new_entry(node) 2.6 node.section = true 2.7 + node.db_time = 0 2.8 node.start_real_time = extos.monotonic_hires_time() 2.9 node.start_proc_time = os.clock() 2.10 - table.insert(trace._stack, node) 2.11 + local stack = trace._stack 2.12 + stack[#stack+1] = node 2.13 return node 2.14 end
3.1 --- a/framework/env/trace/_render_sub_tree.lua Sun Mar 22 19:28:07 2015 +0100 3.2 +++ b/framework/env/trace/_render_sub_tree.lua Sun Mar 22 20:06:26 2015 +0100 3.3 @@ -1,8 +1,16 @@ 3.4 -local function format_time(real_time, proc_time) 3.5 - if proc_time then 3.6 - return string.format("%.1f ms (%.1f ms)", real_time * 1000, proc_time * 1000) 3.7 +local function format_time(db_time) 3.8 + return string.format("%.1f ms", real_time * 1000) 3.9 +end 3.10 + 3.11 +local function format_triple(real_time, proc_time, db_time) 3.12 + if proc_time and db_time then 3.13 + return string.format( 3.14 + "u=%.1f d=%.1f t=%.1f", 3.15 + 1000 * db_time, 3.16 + 1000 * proc_time, 3.17 + 1000 * real_time 3.18 + ) 3.19 else 3.20 - return string.format("%.1f ms", real_time * 1000) 3.21 end 3.22 end 3.23 3.24 @@ -14,29 +22,33 @@ 3.25 if node.start_real_time and node.stop_real_time then 3.26 local total_real_time = node.stop_real_time - node.start_real_time 3.27 local total_proc_time = node.stop_proc_time - node.start_proc_time 3.28 + local total_db_time = node.db_time 3.29 local child_real_time = 0 3.30 local child_proc_time = 0 3.31 + local child_db_time = 0 3.32 for i, child in ipairs(node) do 3.33 if child.start_real_time then 3.34 child_real_time = child_real_time + child.stop_real_time - child.start_real_time 3.35 child_proc_time = child_proc_time + child.stop_proc_time - child.start_proc_time 3.36 + child_db_time = child_db_time + child.db_time 3.37 end 3.38 end 3.39 local real_time = total_real_time - child_real_time 3.40 local proc_time = total_proc_time - child_proc_time 3.41 + local db_time = total_db_time - child_db_time 3.42 slot.put( 3.43 '<div class="time">', 3.44 '<span class="duration_label">this:</span>', 3.45 ' ', 3.46 - '<span class="duration">', format_time(real_time, proc_time), '</span>', 3.47 + '<span class="duration">', format_triple(real_time, proc_time, db_time), '</span>', 3.48 ' | ', 3.49 '<span class="child_duration_label">children:</span>', 3.50 ' ', 3.51 - '<span class="child_duration">', format_time(child_real_time, child_proc_time), '</span>', 3.52 + '<span class="child_duration">', format_triple(child_real_time, child_proc_time, db_time), '</span>', 3.53 ' | ', 3.54 '<span class="total_duration_label">total:</span>', 3.55 ' ', 3.56 - '<span class="total_duration">', format_time(total_real_time, total_proc_time), '</span>', 3.57 + '<span class="total_duration">', format_triple(total_real_time, total_proc_time, db_time), '</span>', 3.58 '</div>' 3.59 ) 3.60 end
4.1 --- a/framework/env/trace/sql.lua Sun Mar 22 19:28:07 2015 +0100 4.2 +++ b/framework/env/trace/sql.lua Sun Mar 22 20:06:26 2015 +0100 4.3 @@ -31,5 +31,8 @@ 4.4 execution_time = execution_time, 4.5 error_position = error_position 4.6 } 4.7 + for i, entry in ipairs(trace._stack) do 4.8 + entry.db_time = entry.db_time + execution_time 4.9 + end 4.10 end 4.11 end