# HG changeset patch
# User jbe
# Date 1427048738 -3600
# Node ID 47c5f33e4a6b682176d9f26357b2d14226eace51
# Parent  e0b6cb626ee612d3fa6e28278e555c8b74402b61
Trace real time and CPU time

diff -r e0b6cb626ee6 -r 47c5f33e4a6b framework/env/trace/__init.lua
--- a/framework/env/trace/__init.lua	Sun Mar 22 18:58:50 2015 +0100
+++ b/framework/env/trace/__init.lua	Sun Mar 22 19:25:38 2015 +0100
@@ -5,7 +5,7 @@
   if seq == 0 then
     -- prepare for configuration/initialization phase
     trace._disabled = false
-    trace._tree = { type = "root", start_hires_time = extos.monotonic_hires_time() }
+    trace._tree = { type = "root" }
     trace._stack = { trace._tree }
     seq = 1
   elseif seq == 1 then
diff -r e0b6cb626ee6 -r 47c5f33e4a6b framework/env/trace/_close_section.lua
--- a/framework/env/trace/_close_section.lua	Sun Mar 22 18:58:50 2015 +0100
+++ b/framework/env/trace/_close_section.lua	Sun Mar 22 19:25:38 2015 +0100
@@ -4,8 +4,8 @@
   if not closed_section then
     error("All trace sections have been closed already.")
   end
-  closed_section.stop_hires_time = extos.monotonic_hires_time()
-  --trace.debug("END " .. extos.monotonic_hires_time() .. " / " .. os.clock())
+  closed_section.stop_real_time = extos.monotonic_hires_time()
+  closed_section.stop_proc_time = os.clock()
   trace._stack[pos] = nil
   return closed_section
 end
diff -r e0b6cb626ee6 -r 47c5f33e4a6b framework/env/trace/_open_section.lua
--- a/framework/env/trace/_open_section.lua	Sun Mar 22 18:58:50 2015 +0100
+++ b/framework/env/trace/_open_section.lua	Sun Mar 22 19:25:38 2015 +0100
@@ -1,8 +1,8 @@
 function trace._open_section(node)
   local node = trace._new_entry(node)
   node.section = true
-  node.start_hires_time = extos.monotonic_hires_time()
+  node.start_real_time = extos.monotonic_hires_time()
+  node.start_proc_time = os.clock()
   table.insert(trace._stack, node)
-  --trace.debug("START " .. extos.monotonic_hires_time() .. " / " .. os.clock())
   return node
 end
diff -r e0b6cb626ee6 -r 47c5f33e4a6b framework/env/trace/_render_sub_tree.lua
--- a/framework/env/trace/_render_sub_tree.lua	Sun Mar 22 18:58:50 2015 +0100
+++ b/framework/env/trace/_render_sub_tree.lua	Sun Mar 22 19:25:38 2015 +0100
@@ -1,5 +1,9 @@
-local function format_time(seconds)
-  return string.format("%.1f ms", seconds * 1000)
+local function format_time(real_time, proc_time)
+  if proc_time then
+    return string.format("%.1f ms (%.1%f ms CPU)", real_time * 1000, proc_time * 1000)
+  else
+    return string.format("%.1f ms", real_time * 1000)
+  end
 end
 
 local function open(class)
@@ -7,36 +11,34 @@
 end
 local function open_head(node)
   slot.put('<div class="trace_head">')
-  if node.start_hires_time and node.stop_hires_time then
-    local total_duration = node.stop_hires_time - node.start_hires_time
-    local child_duration = 0
+  if node.start_real_time and node.stop_real_time then
+    local total_real_time = node.stop_real_time - node.start_real_time
+    local total_proc_time = node.stop_proc_time - node.start_proc_time
+    local child_real_time = 0
+    local child_proc_time = 0
     for i, child in ipairs(node) do
-      if child.start_hires_time and child.stop_hires_time then
-        child_duration = child_duration + child.stop_hires_time - child.start_hires_time
+      if child.start_real_time then
+        child_real_time = child_real_time + child.stop_real_time - child.start_real_time
+        child_proc_time = child_proc_time + child.stop_proc_time - child.start_proc_time
       end
     end
-    local duration = total_duration - child_duration
-    local start_text = math.floor(node.start_hires_time * 10000 + 0.5) / 10
-    local total_duration_text = math.floor(total_duration * 10000 + 0.5) / 10
-    local child_duration_text = math.floor(child_duration * 10000 + 0.5) / 10
-    local duration_text = math.floor(duration * 10000 + 0.5) / 10
-    slot.put('<div class="time">')
-    slot.put('<span class="start_label">start:</span>')
-    slot.put(" ")
-    slot.put('<span class="start">' .. start_text .. 'ms</span>')
-    slot.put(" | ")
-    slot.put('<span class="duration_label">this:</span>')
-    slot.put(" ")
-    slot.put('<span class="duration">' .. duration_text .. 'ms</span>')
-    slot.put(" | ")
-    slot.put('<span class="child_duration_label">children:</span>')
-    slot.put(" ")
-    slot.put('<span class="child_duration">' .. child_duration_text .. 'ms</span>')
-    slot.put(" | ")
-    slot.put('<span class="total_duration_label">total:</span>')
-    slot.put(" ")
-    slot.put('<span class="total_duration">' .. total_duration_text .. 'ms</span>')
-    slot.put('</div>')
+    local real_time = total_real_time - child_real_time
+    local proc_time = total_proc_time - child_proc_time
+    slot.put(
+      '<div class="time">',
+      '<span class="duration_label">this:</span>',
+      ' ',
+      '<span class="duration">', format_time(real_time, proc_time), '</span>',
+      ' | ',
+      '<span class="child_duration_label">children:</span>',
+      ' ',
+      '<span class="child_duration">', format_time(child_real_time, child_proc_time), '</span>',
+      ' | ',
+      '<span class="total_duration_label">total:</span>',
+      ' ',
+      '<span class="total_duration">', format_time(total_real_time, total_proc_time), '</span>',
+      '</div>'
+    )
   end
 end
 local function close_head()