# HG changeset patch
# User bsw
# Date 1404943485 -7200
# Node ID 0de41d8e2cf888b4e981012f6ac8e30964b43545
# Parent  6c4a5b136074bb2d45ed23ddf7d936349eedbaec
Added time protocol to trace system

diff -r 6c4a5b136074 -r 0de41d8e2cf8 framework/env/trace/__init.lua
--- a/framework/env/trace/__init.lua	Mon Feb 10 20:52:21 2014 +0100
+++ b/framework/env/trace/__init.lua	Thu Jul 10 00:04:45 2014 +0200
@@ -1,3 +1,3 @@
 trace._disabled = false
-trace._tree = { type = "root" }
+trace._tree = { type = "root", start_hires_time = extos.monotonic_hires_time() }
 trace._stack = { trace._tree }
diff -r 6c4a5b136074 -r 0de41d8e2cf8 framework/env/trace/_close_section.lua
--- a/framework/env/trace/_close_section.lua	Mon Feb 10 20:52:21 2014 +0100
+++ b/framework/env/trace/_close_section.lua	Thu Jul 10 00:04:45 2014 +0200
@@ -4,6 +4,7 @@
   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())
   trace._stack[pos] = nil
   return closed_section
diff -r 6c4a5b136074 -r 0de41d8e2cf8 framework/env/trace/_open_section.lua
--- a/framework/env/trace/_open_section.lua	Mon Feb 10 20:52:21 2014 +0100
+++ b/framework/env/trace/_open_section.lua	Thu Jul 10 00:04:45 2014 +0200
@@ -1,6 +1,7 @@
 function trace._open_section(node)
   local node = trace._new_entry(node)
   node.section = true
+  node.start_hires_time = extos.monotonic_hires_time()
   table.insert(trace._stack, node)
   --trace.debug("START " .. extos.monotonic_hires_time() .. " / " .. os.clock())
   return node
diff -r 6c4a5b136074 -r 0de41d8e2cf8 framework/env/trace/_render_sub_tree.lua
--- a/framework/env/trace/_render_sub_tree.lua	Mon Feb 10 20:52:21 2014 +0100
+++ b/framework/env/trace/_render_sub_tree.lua	Thu Jul 10 00:04:45 2014 +0200
@@ -1,8 +1,39 @@
 local function open(class)
   slot.put('<li class="trace_' .. class .. '">')
 end
-local function open_head()
+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
+    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
+      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>')
+  end
 end
 local function close_head()
   slot.put('</div>')
@@ -55,7 +86,7 @@
     close()
   elseif node_type == "request" then
     open("request")
-    open_head()
+    open_head(node)
     slot.put("REQUESTED")
     if node.view then
       slot.put(" VIEW")
@@ -71,17 +102,17 @@
     close_with_children()
   elseif node_type == "config" then
     open("config")
-    open_head()
+    open_head(node)
     slot.put('Configuration "', encode.html(node.name), '"')
     close_with_children()
   elseif node_type == "filter" then
     open("filter")
-    open_head()
+    open_head(node)
     slot.put(encode.html(node.path))
     close_with_children()
   elseif node_type == "view" then
     open("view")
-    open_head()
+    open_head(node)
     slot.put(
       "EXECUTE VIEW: ",
       encode.html(node.module),
@@ -107,7 +138,7 @@
     else
       open("action_neutral")
     end
-    open_head()
+    open_head(node)
     slot.put(
       "EXECUTE ACTION: ",
       encode.html(node.module),
@@ -127,17 +158,17 @@
     close()
   elseif node_type == "redirect" then
     open("redirect")
-    open_head()
+    open_head(node)
     slot.put("303 REDIRECT TO VIEW: ", encode.html(node.module), "/", encode.html(node.view))
     close_with_children()
   elseif node_type == "forward" then
     open("forward")
-    open_head()
+    open_head(node)
     slot.put("INTERNAL FORWARD TO VIEW: ", encode.html(node.module), "/", encode.html(node.view))
     close_with_children()
   elseif node_type == "exectime" then
     open("exectime")
-    open_head()
+    open_head(node)
     slot.put(
       "Finished after " ..
       string.format("%.1f", extos.monotonic_hires_time() * 1000) ..
@@ -164,7 +195,7 @@
     close();
   elseif node_type == "error" then
     open("error")
-    open_head()
+    open_head(node)
     slot.put("UNEXPECTED ERROR")
     close_head()
     close()