Introduce support for guest-defined trace markers.

accel/tcg/log_instr_text.c

@@ -215,6 +215,9 @@ void emit_text_instr(CPUArchState *env, cpu_log_entry_t *entry)
                      event->ctx_update.pid, event->ctx_update.tid,
                      event->ctx_update.cid);
             break;
+        case LOG_EVENT_MARKER:
+            qemu_log("Guest trace marker %lx\n", event->marker);
+            break;
         default:
             assert(0 && "unknown event ID");
         }

include/exec/log_instr.h

@@ -189,21 +189,34 @@ void qemu_log_printf_create_globals(void);
 struct cpu_log_entry;
 
 /*
- * Request a flush of the TCG when changing loglevel outside of qemu_log_instr.
- * TODO(am2419): this should be removed from the interface.
+ * Check whether instruction tracing is enabled.
+ * Note: changes to the instruction logging flags result in a call to
+ * tb_flush so we can do the logging checks at translate time as well.
  */
-void qemu_log_instr_flush_tcg(bool request_stop);
+bool qemu_log_instr_check_enabled(CPUArchState *env);
 
 /* Helper macro to check for instruction logging enabled */
 #define qemu_log_instr_enabled(env)                                            \
     unlikely(qemu_log_instr_check_enabled((env)))
 
 /*
- * Check whether instruction tracing is enabled.
- * Note: changes to the instruction logging flags result in a call to
- * tb_flush so we can do the logging checks at translate time as well.
+ * Helper macro to check whether an event should be appended to the trace or not.
+ * This takes into account the event data to allow some events to be appended to
+ * the current log buffer entry even when tracing is disabled.
+ * These events will only become visible in the trace when tracing is started,
+ * in the first log entry.
+ * This is intended to be used only for OS-driven events that are relatively
+ * low-frequency w.r.t. the number of instructions executed.
  */
-bool qemu_log_instr_check_enabled(CPUArchState *env);
+static inline bool qemu_log_instr_event_enabled(CPUArchState *env, log_event_t *event)
+{
+    if (event->id == LOG_EVENT_MARKER)
+        return true;
+    if (event->id == LOG_EVENT_CTX_UPDATE &&
+        event->ctx_update.op == LOG_EVENT_CTX_OP_SETUP)
+        return true;
+    return qemu_log_instr_check_enabled(env);
+}
 
 /*
  * Register a trace filter for a given CPU.

include/exec/log_instr_perfetto.h

@@ -60,7 +60,8 @@ PERFETTO_DEFINE_CATEGORIES(
     perfetto::Category("stats").SetDescription("High-level statistics data"),
     perfetto::Category("ctrl").SetDescription("Tracing control events"),
     perfetto::Category("trap").SetDescription("CPU trap events"),
-    perfetto::Category("sched").SetDescription("Scheduling events"));
+    perfetto::Category("sched").SetDescription("Scheduling events"),
+    perfetto::Category("marker").SetDescription("Guest trace timestamp markers"));
 #endif
 
 /*

include/qemu/log_instr.h

@@ -101,7 +101,11 @@ typedef enum {
 /*
  * Trace event identifiers.
  */
-typedef enum { LOG_EVENT_STATE = 0, LOG_EVENT_CTX_UPDATE = 1 } log_event_id_t;
+typedef enum {
+    LOG_EVENT_STATE = 0,
+    LOG_EVENT_CTX_UPDATE = 1,
+    LOG_EVENT_MARKER = 2
+} log_event_id_t;
 
 /*
  * Tracing status changed (e.g. trace start/stop)
@@ -151,6 +155,7 @@ typedef struct {
     union {
         log_event_trace_state_update_t state;
         log_event_ctx_update_t ctx_update;
+        uint64_t marker;
     };
 } log_event_t;
 

target/riscv/op_helper_log_instr.c

@@ -84,13 +84,14 @@ void HELPER(riscv_log_instr_event)(CPURISCVState *env, target_ulong pc)
         event.ctx_update.cid = get_gpr_value(env, 14);
         event.ctx_update.mode = cpu_priv_to_mode(env->priv);
         break;
+    case LOG_EVENT_MARKER:
+        event.marker = get_gpr_value(env, 11);
+        break;
     default:
         warn_report("Unsupported event ID for TCG instr logging %d", event.id);
         return;
     }
-    if (!qemu_log_instr_enabled(env) &&
-        (event.id != LOG_EVENT_CTX_UPDATE ||
-         event.ctx_update.op != LOG_EVENT_CTX_OP_SETUP))
+    if (!qemu_log_instr_event_enabled(env, &event))
         return;
     qemu_log_instr_event(env, &event);
 }

trace_extra/trace_perfetto.cc

@@ -179,47 +179,65 @@ void process_events(perfetto_backend_data *data, cpu_log_entry_handle entry)
 {
     int nevents = perfetto_log_entry_events(entry);
     bool have_startstop_event = false;
-    auto *curr_ctx_data = &data->ctx_tracker_.get_ctx_data();
-    auto *curr_ctx_track = &data->ctx_tracker_.get_ctx_track();
+    auto *ctx_data = &data->ctx_tracker_.get_ctx_data();
+    auto *ctx_track = &data->ctx_tracker_.get_ctx_track();
 
     /*
      * Note: LOG_EVENT_STATE events are emitted even when tracing is disabled.
      * The rest of the events should only be emitted when tracing is active.
      */
     for (int i = 0; i < nevents; i++) {
         log_event_t *evt = perfetto_log_event(entry, i);
-        if (evt->id == LOG_EVENT_STATE) {
-            switch (evt->state.next_state) {
-            case LOG_EVENT_STATE_FLUSH:
-                TRACE_EVENT_INSTANT("ctrl", "flush", data->ctrl_track_);
-                data->ctx_tracker_.flush_all_ctx_data();
-                perfetto::TrackEvent::Flush();
+        switch (evt->id) {
+            case LOG_EVENT_STATE:
+                {
+                    switch (evt->state.next_state) {
+                        case LOG_EVENT_STATE_FLUSH:
+                            TRACE_EVENT_INSTANT("ctrl", "flush", data->ctrl_track_);
+                            data->ctx_tracker_.flush_all_ctx_data();
+                            perfetto::TrackEvent::Flush();
+                            break;
+                        case LOG_EVENT_STATE_START:
+                            ctx_data->stats.unpause(*ctx_track, evt->state.pc);
+                            TRACE_EVENT_BEGIN("ctrl", "tracing", data->ctrl_track_);
+                            have_startstop_event = true;
+                            break;
+                        case LOG_EVENT_STATE_STOP:
+                            ctx_data->stats.pause(*ctx_track, evt->state.pc);
+                            TRACE_EVENT_END("ctrl", data->ctrl_track_);
+                            have_startstop_event = true;
+                            break;
+                        default:
+                            assert(false && "Invalid state event");
+                    }
+                }
                 break;
-            case LOG_EVENT_STATE_START:
-                curr_ctx_data->stats.unpause(*curr_ctx_track, evt->state.pc);
-                TRACE_EVENT_BEGIN("ctrl", "tracing", data->ctrl_track_);
-                have_startstop_event = true;
+            case LOG_EVENT_CTX_UPDATE:
+                {
+                    /* Swap current context. */
+                    if (evt->ctx_update.op == LOG_EVENT_CTX_OP_SETUP ||
+                        evt->ctx_update.op == LOG_EVENT_CTX_OP_SWITCH) {
+                        ctx_data->stats.pause(*ctx_track, perfetto_log_entry_pc(entry));
+                        data->ctx_tracker_.context_update(&evt->ctx_update);
+                        /* Reload data and track as context_update will have changed them */
+                        ctx_data = &data->ctx_tracker_.get_ctx_data();
+                        ctx_track = &data->ctx_tracker_.get_ctx_track();
+                        ctx_data->stats.unpause(*ctx_track, perfetto_log_entry_pc(entry));
+                    }
+                }
                 break;
-            case LOG_EVENT_STATE_STOP:
-                curr_ctx_data->stats.pause(*curr_ctx_track, evt->state.pc);
-                TRACE_EVENT_END("ctrl", data->ctrl_track_);
-                have_startstop_event = true;
+            case LOG_EVENT_MARKER:
+                {
+                    auto cpu_track = data->ctx_tracker_.get_cpu_track();
+                    TRACE_EVENT_INSTANT("marker", "guest", cpu_track,
+                        [&](perfetto::EventContext ctx) {
+                            auto *qemu_arg = ctx.event()->set_qemu();
+                            qemu_arg->set_marker(evt->marker);
+                        });
+                }
                 break;
             default:
-                assert(false && "Invalid state event");
-            }
-        } else if (evt->id == LOG_EVENT_CTX_UPDATE) {
-            // Swap current context.
-            if (evt->ctx_update.op == LOG_EVENT_CTX_OP_SETUP ||
-                evt->ctx_update.op == LOG_EVENT_CTX_OP_SWITCH) {
-                curr_ctx_data->stats.pause(*curr_ctx_track,
-                                           perfetto_log_entry_pc(entry));
-                data->ctx_tracker_.context_update(&evt->ctx_update);
-                curr_ctx_data = &data->ctx_tracker_.get_ctx_data();
-                curr_ctx_track = &data->ctx_tracker_.get_ctx_track();
-                curr_ctx_data->stats.unpause(*curr_ctx_track,
-                                             perfetto_log_entry_pc(entry));
-            }
+                assert(false && "Invalid event identifier");
         }
     }
     if (perfetto_log_entry_flags(entry) & LI_FLAG_MODE_SWITCH) {
@@ -228,13 +246,11 @@ void process_events(perfetto_backend_data *data, cpu_log_entry_handle entry)
         // XXX-AM: consider making the mode switch an event, possibly with its
         // own separate pc signaling the PC of the next instruction we are
         // landing to?
-        curr_ctx_data->stats.pause(*curr_ctx_track,
-                                   perfetto_log_entry_pc(entry));
+        ctx_data->stats.pause(*ctx_track, perfetto_log_entry_pc(entry));
         data->ctx_tracker_.mode_update(mode);
-        curr_ctx_data = &data->ctx_tracker_.get_ctx_data();
-        curr_ctx_track = &data->ctx_tracker_.get_ctx_track();
-        curr_ctx_data->stats.unpause(*curr_ctx_track,
-                                     perfetto_log_entry_pc(entry));
+        ctx_data = &data->ctx_tracker_.get_ctx_data();
+        ctx_track = &data->ctx_tracker_.get_ctx_track();
+        ctx_data->stats.unpause(*ctx_track, perfetto_log_entry_pc(entry));
     }
 
     /*
@@ -245,7 +261,7 @@ void process_events(perfetto_backend_data *data, cpu_log_entry_handle entry)
      */
     if (!have_startstop_event &&
         (perfetto_log_entry_flags(entry) & LI_FLAG_HAS_INSTR_DATA) != 0)
-        curr_ctx_data->stats.process_instr(*curr_ctx_track, entry);
+        ctx_data->stats.process_instr(*ctx_track, entry);
 }
 
 void process_instr(perfetto_backend_data *data, cpu_log_entry_handle entry)
@@ -256,8 +272,7 @@ void process_instr(perfetto_backend_data *data, cpu_log_entry_handle entry)
      * same track/category: e.g. mode swtich, interrupt information and modified
      * registers?
      */
-    TRACE_EVENT_INSTANT(
-        "instructions", "stream", data->ctx_tracker_.get_ctx_track(),
+    TRACE_EVENT_INSTANT("instructions", "stream", data->ctx_tracker_.get_ctx_track(),
         [&](perfetto::EventContext ctx) {
             auto *qemu_arg = ctx.event()->set_qemu();
             auto *instr = qemu_arg->set_instr();