annotate all trace events with the current tag

Author: cmnrd

include/reactor-cpp/trace.hh

@@ -37,11 +37,15 @@ TRACEPOINT_EVENT(
   reaction_execution_starts,
   TP_ARGS(
     int, worker_id_arg,
-    const std::string&, reaction_name_arg
+    const std::string&, reaction_name_arg,
+    const reactor::LogicalTime&, tag_arg
   ),
   TP_FIELDS(
     ctf_string(reaction_name, reaction_name_arg.c_str())
     ctf_integer(int, worker_id, worker_id_arg)
+    ctf_integer(unsigned long, timestamp_ns,
+                tag_arg.time_point().time_since_epoch().count())
+    ctf_integer(unsigned, timestamp_microstep, tag_arg.micro_step())
   )
 )
 
@@ -50,11 +54,15 @@ TRACEPOINT_EVENT(
   reaction_execution_finishes,
   TP_ARGS(
     int, worker_id_arg,
-    const std::string&, reaction_name_arg
+    const std::string&, reaction_name_arg,
+    const reactor::LogicalTime&, tag_arg
   ),
   TP_FIELDS(
     ctf_string(reaction_name, reaction_name_arg.c_str())
     ctf_integer(int, worker_id, worker_id_arg)
+    ctf_integer(unsigned long, timestamp_ns,
+                tag_arg.time_point().time_since_epoch().count())
+    ctf_integer(unsigned, timestamp_microstep, tag_arg.micro_step())
   )
 )
 

lib/scheduler.cc

@@ -70,9 +70,11 @@ void Worker::work() const {
 void Worker::execute_reaction(Reaction* reaction) const {
   log::Debug() << "(Worker " << id << ") "
                << "execute reaction " << reaction->fqn();
-  tracepoint(reactor_cpp, reaction_execution_starts, id, reaction->fqn());
+  tracepoint(reactor_cpp, reaction_execution_starts, id, reaction->fqn(),
+             scheduler.logical_time());
   reaction->trigger();
-  tracepoint(reactor_cpp, reaction_execution_finishes, id, reaction->fqn());
+  tracepoint(reactor_cpp, reaction_execution_finishes, id, reaction->fqn(),
+             scheduler.logical_time());
 }
 
 void Scheduler::schedule() {

tracing/ctf_to_json.py

@@ -144,6 +144,10 @@ def reaction_execution_starts_to_dict(msg):
         "ts": get_timestamp_us(msg),
         "pid": 0,
         "tid": int(event["worker_id"]),
+        "args": {
+            "microstep": int(event["timestamp_microstep"]),
+            "timestamp_ns": int(event["timestamp_ns"])
+        }
     }
 
 
@@ -156,6 +160,10 @@ def reaction_execution_finishes_to_dict(msg):
         "ts": get_timestamp_us(msg),
         "pid": 0,
         "tid": int(event["worker_id"]),
+        "args": {
+            "microstep": int(event["timestamp_microstep"]),
+            "timestamp_ns": int(event["timestamp_ns"])
+        }
     }
 
 
@@ -172,7 +180,8 @@ def schedule_action_to_dict(msg):
         "s": "t",
         "cname": "terrible",
         "args": {
-            "microstep": int(event["timestamp_microstep"])
+            "microstep": int(event["timestamp_microstep"]),
+            "timestamp_ns": int(event["timestamp_ns"])
         }
     }
 
@@ -190,7 +199,8 @@ def trigger_reaction_to_dict(msg):
         "s": "t",
         "cname": "light_memory_dump",
         "args": {
-            "microstep": int(event["timestamp_microstep"])
+            "microstep": int(event["timestamp_microstep"]),
+            "timestamp_ns": int(event["timestamp_ns"])
         }
     }