LithosAnanke/src/starkernel/doe_log.c

/*
  StarForth — Steady-State Virtual Machine Runtime

  Copyright (c) 2023–2025 Robert A. James
  All rights reserved.

  Licensed under the StarForth License, Version 1.0
*/

/**
 * doe_log.c — DoE CSV logger for the LithosAnanke kernel
 *
 * Emits CSV rows to the serial log once per heartbeat tick. Each row is
 * prefixed with a cyan [HADES][DOE ] tag so it can be extracted cleanly:
 *
 *   grep -aP '\[HADES\]\[DOE \]' qemu-amd64-*.log
 *
 * Columns (in order):
 *   0a. vm_name                string  — the emitting VM's own registry name
 *                                        (reverse lookup on vm->stadium_vm_id,
 *                                        "?" if unregistered at this tick).
 *                                        Added 2026-09-16 for the multiuser/
 *                                        multitasking DoE (FABRIC-3.md
 *                                        §XXXIII): every prior column already
 *                                        described *a* VM's state each row,
 *                                        but nothing said *which* VM emitted
 *                                        it, making concurrent-VM rows
 *                                        indistinguishable by source.
 *   0b. vm_id_hex              string  — the emitting VM's own stadium_vm_id
 *                                        as "hi-lo" hex, same format
 *                                        PARITY:BIRTH/PARITY:KILL already
 *                                        print. Names get reused across a
 *                                        trial's own KILL+rebirth cycles;
 *                                        this is the one column unique to a
 *                                        single birth instance.
 *   1.  tick_number           uint32  — monotonic heartbeat counter
 *   2.  elapsed_ns            uint64  — ns since run start
 *   3.  tick_interval_ns      uint64  — actual interval from prior tick
 *   4.  cache_hits_delta       uint32  — hot-words cache hits this tick (TODO: 0)
 *   5.  bucket_hits_delta      uint32  — bucket hits this tick (TODO: 0)
 *   6.  word_executions_delta  uint32  — words executed this tick (TODO: 0)
 *   7.  hot_word_count         uint64  — words with heat >= threshold
 *   8.  avg_word_heat_q48      uint64  — mean execution heat as raw Q48.16 integer
 *   9.  window_width           uint32  — rolling window effective size
 *   10. actual_window_size     uint32  — true analysis width: min(total_executions, effective_window_size)
 *   11. predicted_label_hits   uint32  — ANOVA early-exit confirmations per tick (L8 validation signal)
 *   12. jitter_bits            uint64  — estimated_jitter_ns IEEE 754 raw bits (union-punned)
 *   13. apic_ticks             uint64  — APIC timer monotonic tick count
 *   14. time_trust_q48         uint64  — TIME-TRUST in Q48.16 format
 *   15. variance_q48           uint64  — timing variance in Q48.16 format
 *   16. hera_heat_q48          uint64  — VM fleet physics: Hera's execution_heat_q48
 *   17. hermes_heat_q48        uint64  — VM fleet physics: Hermes's execution_heat_q48
 *   18. artemis_heat_q48       uint64  — VM fleet physics: Artemis's execution_heat_q48
 *   19. fleet_k_q48            uint64  — "K": vm_physics_fleet_heat_sum() over ALL live
 *                                        VMs (not just the 3 named Tripod members above --
 *                                        this is the genuine conservation invariant, which
 *                                        should read Q48_ONE (65536) whenever conservation
 *                                        holds). Requested 2026-09-12 alongside the 3x9
 *                                        factorial analysis in experiments/std79-doe/ --
 *                                        columns 16-18 alone cannot reconstruct this since
 *                                        they omit every identity VM's own heat.
 *   20. fleet_conserved        uint32  — vm_physics_conserved() as 0/1: whether
 *                                        |fleet_k_q48 - Q48_ONE| < VM_PHYSICS_EPSILON_Q48
 *                                        at the moment this row was captured.
 *   21. switch_count_cumulative uint64 — Stage 3 preemptive-switch count, cumulative
 *                                        since boot (capsule_vm_switch_signal.c).
 *   22. switch_current_slot     uint32 — which registered switch-signal participant is
 *                                        executing at this tick (0=Hera,1=Hermes,
 *                                        2=Artemis by current registration order;
 *                                        0xFFFFFFFF = none/unregistered at this moment).
 *   23. switch_hera_readiness   uint32 — Hera's raw readiness accumulator (slot 0).
 *   24. switch_hermes_readiness uint32 — Hermes's raw readiness accumulator (slot 1).
 *   25. switch_artemis_readiness uint32 — Artemis's raw readiness accumulator (slot 2).
 *   26. switch_ticks_since      uint32 — ticks elapsed since the last real switch
 *                                        (capsule_vm_switch_signal.c); empirically
 *                                        verifies the fixed 50-tick threshold under
 *                                        real DoE load rather than assuming it.
 *
 *   Columns 21-26 (FABRIC-3.md §XXVIII Stage 3 follow-on, 2026-09-13): added
 *   alongside Stage 3's timer-driven preemptive context switching -- read-only
 *   exposure of state the switch-signal module already tracked internally for its
 *   own decision-making; no new measurement logic, just made observable. Slot
 *   readiness columns are hardcoded to the 3 known Tripod slots (same convention
 *   as columns 16-18) rather than a dynamic per-slot column set, for the same
 *   reason: this is a logging schema for the currently-known fleet, not the
 *   switch-signal mechanism itself (which stays slot-count-agnostic, headroom for
 *   up to 8 participants -- see capsule_vm_switch_signal.h).
 *
 * Note: avg_word_heat and estimated_jitter_ns are stored as double in the
 * snapshot but the freestanding snprintf has no %%f support. avg_word_heat
 * is emitted as raw Q48.16 (multiply by 65536); jitter is union-punned to its
 * IEEE 754 uint64 bit pattern to avoid UB from out-of-range cast.
 *
 * Columns 16-18 (VM-FLEET-ATTRACTOR-DESIGN-20260705.md, Phase 3): looked up
 * by name each tick rather than by a fixed vm_id, since kill/rebirth (e.g.
 * TRIPOD-TEST's K-soak) assigns a fresh vm_id on every rebirth. Fixed to the
 * three known Tripod VMs, not a dynamic per-VM column set -- this is a
 * logging schema for a specific known fleet, not the physics mechanism
 * itself (which stays genuinely VM-count-agnostic). Reads 0 for any VM not
 * currently found in the registry (e.g. Hermes momentarily during its
 * kill/rebirth window), which is a legitimate observation, not an error.
 */

#include "starkernel/doe_log.h"
#include "starkernel/console.h"
#include "starkernel/timer.h"
#include "starkernel/capsule_birth.h"
#include "starkernel/capsule_vm_physics.h"
#include "starkernel/capsule_vm_switch_signal.h" /* FABRIC-3.md §XXVIII Stage 3 follow-on */
#include "freestanding/stdio.h"
#include "word_registry.h"

int g_doe_log_enabled = 0; /* off by default -- HB-ON to enable, per instruction */

#define DOE_PREFIX   "\x1b[36m[HADES][DOE ]\x1b[0m "
#define DOE_BUF_SIZE 512

static const char *doe_header =
    DOE_PREFIX
    "vm_name,vm_id_hex,"
    "tick_number,elapsed_ns,tick_interval_ns,"
    "cache_hits_delta,bucket_hits_delta,word_executions_delta,"
    "hot_word_count,avg_word_heat_q48,"
    "window_width,actual_window_size,predicted_label_hits,jitter_bits,"
    "apic_ticks,time_trust_q48,variance_q48,vm_call_depth_max,"
    "hera_heat_q48,hermes_heat_q48,artemis_heat_q48,"
    "fleet_k_q48,fleet_conserved,"
    "switch_count_cumulative,switch_current_slot,"
    "switch_hera_readiness,switch_hermes_readiness,switch_artemis_readiness,"
    "switch_ticks_since";

/* Looks up a Tripod VM's fleet heat by name; 0 if not currently registered
 * (e.g. between KILL and rebirth). */
static uint64_t doe_log_heat_by_name(const char *name)
{
    VMRegistryEntry entry;
    if (capsule_vm_find_by_name_nocase(name, &entry) != 0) return 0;
    return vm_physics_heat_of(entry.vm_id);
}

void doe_log_tick_row(VM *vm, const HeartbeatTickSnapshot *snap)
{
    if (!g_doe_log_enabled)
        return;
    if (!snap)
        return;

    /* Print header once before the first data row */
    static int header_printed = 0;
    if (!header_printed) {
        console_puts(doe_header);
        console_puts("\r\n");
        header_printed = 1;
    }

    /* Pull APIC timer trust state */
    const TimeTrustState *ts = heartbeat_state();
    uint64_t apic_ticks     = ts ? ts->ticks              : 0;
    uint64_t time_trust_q48 = ts ? (uint64_t)ts->trust    : 0;
    uint64_t variance_q48   = ts ? (uint64_t)ts->variance : 0;

    /* Convert doubles to integer-safe representations (freestanding snprintf has no %f).
     * Use union punning for jitter to avoid UB from out-of-range double→int64 cast. */
    uint64_t avg_heat_q48 = (uint64_t)(snap->avg_word_heat * 65536.0);
    union { double d; uint64_t u; } jitter_bits;
    jitter_bits.d = snap->estimated_jitter_ns;
    uint64_t jitter_raw = jitter_bits.u;

    /* Format the 20-column CSV row into a local buffer.
     * Use %llu (unsigned long long) for all uint64_t fields — %lu is unreliable
     * for values > 2^32 on aarch64 due to mixed-width varargs ABI behaviour. */
    unsigned vm_call_depth_max = (vm && vm->call_stack_max > 0) ? (unsigned)vm->call_stack_max : 0;

    /* Identity columns (2026-09-16, FABRIC-3.md §XXXIII): reverse-lookup
     * this row's own emitting VM by its stadium_vm_id -- name can be
     * reused across a KILL+rebirth cycle, so vm_id_hex is what actually
     * disambiguates one birth instance from the next. "?" name / all-zero
     * id if vm is NULL or not (yet) registered, never a crash. */
    const char *vm_name = "?";
    char        vm_id_hex[34] = "0000000000000000-0000000000000000";
    if (vm) {
        VMRegistryEntry self_entry;
        if (capsule_vm_registry_get(vm->stadium_vm_id, &self_entry) == 0) {
            vm_name = self_entry.name;
        }
        /* Hand-rolled hex, not snprintf("%016llx", ...) -- found live
         * (2026-09-16) that this freestanding snprintf doesn't support
         * width+ll+x and silently prints the literal format string
         * instead of substituting. Same nibble-table idiom vm_uuid.c's
         * own vm_uuid_format() and MINT-SCRATCH-EMIT already use. */
        {
            static const char hexd[] = "0123456789abcdef";
            uint64_t halves[2] = { vm->stadium_vm_id.hi, vm->stadium_vm_id.lo };
            int pos = 0, h;
            for (h = 0; h < 2; h++) {
                int i;
                for (i = 15; i >= 0; i--) {
                    vm_id_hex[pos++] = hexd[(halves[h] >> (i * 4)) & 0xF];
                }
                if (h == 0) vm_id_hex[pos++] = '-';
            }
            vm_id_hex[pos] = '\0';
        }
    }

    uint64_t hera_heat_q48    = doe_log_heat_by_name("Hera");
    uint64_t hermes_heat_q48  = doe_log_heat_by_name("Hermes");
    uint64_t artemis_heat_q48 = doe_log_heat_by_name("Artemis");
    uint64_t fleet_k_q48      = vm_physics_fleet_heat_sum();
    unsigned fleet_conserved  = vm_physics_conserved() ? 1u : 0u;

    /* FABRIC-3.md §XXVIII Stage 3 follow-on (2026-09-13): switch-signal
     * exposure, looked up by name each tick (same convention as the heat
     * columns above -- registration order is not assumed fixed). */
    uint64_t switch_count       = sk_vm_switch_signal_switch_count();
    int      switch_slot        = sk_vm_switch_signal_current_slot();
    unsigned switch_current_slot = (switch_slot >= 0) ? (unsigned)switch_slot : 0xFFFFFFFFu;
    uint32_t switch_ticks_since = sk_vm_switch_signal_ticks_since_switch();
    uint32_t hera_readiness = 0, hermes_readiness = 0, artemis_readiness = 0;
    {
        VMRegistryEntry e;
        if (capsule_vm_find_by_name_nocase("Hera", &e) == 0)
            hera_readiness = sk_vm_switch_signal_readiness_of(e.vm_id);
        if (capsule_vm_find_by_name_nocase("Hermes", &e) == 0)
            hermes_readiness = sk_vm_switch_signal_readiness_of(e.vm_id);
        if (capsule_vm_find_by_name_nocase("Artemis", &e) == 0)
            artemis_readiness = sk_vm_switch_signal_readiness_of(e.vm_id);
    }

    char buf[DOE_BUF_SIZE];
    snprintf(buf, sizeof(buf),
             "%s,%s,"
             "%u,%llu,%llu,%u,%u,%u,%llu,%llu,%u,%u,%u,%llu,%llu,%llu,%llu,%u,%llu,%llu,%llu,%llu,%u,"
             "%llu,%u,%u,%u,%u,%u",
             vm_name,
             vm_id_hex,
             snap->tick_number,
             (unsigned long long)snap->elapsed_ns,
             (unsigned long long)snap->tick_interval_ns,
             snap->cache_hits_delta,
             snap->bucket_hits_delta,
             snap->word_executions_delta,
             (unsigned long long)snap->hot_word_count,
             (unsigned long long)avg_heat_q48,
             snap->window_width,
             snap->actual_window_size,
             snap->predicted_label_hits,
             (unsigned long long)jitter_raw,
             (unsigned long long)apic_ticks,
             (unsigned long long)time_trust_q48,
             (unsigned long long)variance_q48,
             vm_call_depth_max,
             (unsigned long long)hera_heat_q48,
             (unsigned long long)hermes_heat_q48,
             (unsigned long long)artemis_heat_q48,
             (unsigned long long)fleet_k_q48,
             fleet_conserved,
             (unsigned long long)switch_count,
             switch_current_slot,
             hera_readiness,
             hermes_readiness,
             artemis_readiness,
             switch_ticks_since);

    console_puts(DOE_PREFIX);
    console_puts(buf);
    console_puts("\r\n");
}

/* HB-ON ( -- ): enable per-tick DoE instrumentation (g_doe_log_enabled=1). */
static void doe_word_hb_on(VM *vm)
{
    (void)vm;
    g_doe_log_enabled = 1;
}

/* HB-OFF ( -- ): disable per-tick DoE instrumentation (g_doe_log_enabled=0). */
static void doe_word_hb_off(VM *vm)
{
    (void)vm;
    g_doe_log_enabled = 0;
}

void register_doe_log_words(VM *vm)
{
    register_word(vm, "HB-ON", doe_word_hb_on);
    register_word(vm, "HB-OFF", doe_word_hb_off);
}