LithosAnanake/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 20-column 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):
 *   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
    "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;

    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),
             "%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",
             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);
}