[autoresearch] baseline: system prompt quality tests (5/5 passing)

crates/inference-core/src/engine.rs

@@ -157,19 +157,28 @@ impl InferenceEngine {
             bail!("Model file not found: {}", config.model_path.display());
         }
 
+        let model_name = config
+            .model_path
+            .file_name()
+            .map(|s| s.to_string_lossy().into_owned())
+            .unwrap_or_else(|| "<unknown>".into());
+
         info!(
-            model = %config.model_path.display(),
-            profile = ?config.profile,
-            n_gpu_layers = config.n_gpu_layers,
-            n_ctx = config.n_ctx,
-            n_batch = config.n_batch,
-            n_ubatch = config.n_ubatch,
+            model      = %model_name,
+            profile    = ?config.profile,
+            gpu_layers = config.n_gpu_layers,
+            n_ctx      = config.n_ctx,
+            n_batch    = config.n_batch,
+            n_ubatch   = config.n_ubatch,
             flash_attn = config.flash_attn,
-            use_mmap = config.use_mmap,
-            "Loading model via llama-sys"
+            use_mmap   = config.use_mmap,
+            "engine_config"
         );
 
+        let t_total = std::time::Instant::now();
+
         // 1. Load dynamic library
+        let t0 = std::time::Instant::now();
         let lib = Arc::new(LlamaLib::load_auto().context("Failed to load llama.dll")?);
 
         // 2. Backend init
@@ -177,7 +186,10 @@ impl InferenceEngine {
             (lib.backend_load_all)();
             (lib.backend_init)();
         }
-        info!("llama backend initialised");
+        info!(
+            elapsed_ms = t0.elapsed().as_millis(),
+            "llama backend initialised"
+        );
 
         // 3. Model params
         let mut mparams = unsafe { (lib.model_default_params)() };
@@ -188,10 +200,12 @@ impl InferenceEngine {
         let model_path_c = CString::new(config.model_path.to_str().context("Non-UTF8 model path")?)
             .context("CString::new failed")?;
 
+        let t_load = std::time::Instant::now();
         let model_ptr = unsafe { (lib.model_load_from_file)(model_path_c.as_ptr(), mparams) };
         if model_ptr.is_null() {
             bail!("llama_model_load_from_file returned NULL – check model path and VRAM");
         }
+        let load_ms = t_load.elapsed().as_millis();
 
         // Log model info
         {
@@ -206,11 +220,12 @@ impl InferenceEngine {
             let is_hybrid = unsafe { (lib.model_is_hybrid)(model_ptr) };
             let is_recurrent = unsafe { (lib.model_is_recurrent)(model_ptr) };
             info!(
-                desc = %desc_str,
-                params_b = n_params as f64 / 1e9,
+                desc         = %desc_str,
+                params_b     = format!("{:.2}", n_params as f64 / 1e9),
                 is_hybrid,
                 is_recurrent,
-                "Model loaded"
+                load_ms,
+                "model_loaded"
             );
         }
 
@@ -241,7 +256,11 @@ impl InferenceEngine {
         }
 
         let actual_ctx = unsafe { (lib.n_ctx)(ctx_ptr) };
-        info!(n_ctx = actual_ctx, "Context initialised");
+        info!(
+            n_ctx = actual_ctx,
+            elapsed_ms = t_total.elapsed().as_millis(),
+            "context_ready"
+        );
 
         let ctx = OwnedContext {
             ptr: ctx_ptr,
@@ -260,7 +279,8 @@ impl InferenceEngine {
     ///
     /// Call once after `load()` before accepting real requests.
     pub fn warmup(&mut self) -> Result<()> {
-        info!("Running engine warmup (dummy decode)…");
+        let t = std::time::Instant::now();
+        info!("engine_warmup: starting dummy decode to pre-allocate CUDA buffers");
 
         unsafe {
             (self.lib.set_warmup)(self.ctx.ptr, true);
@@ -271,18 +291,18 @@ impl InferenceEngine {
             let ret = (self.lib.decode)(self.ctx.ptr, batch);
             (self.lib.set_warmup)(self.ctx.ptr, false);
             if ret != 0 {
-                warn!(ret, "Warmup decode returned non-zero (non-fatal)");
+                warn!(ret, "engine_warmup: decode returned non-zero (non-fatal)");
             }
 
             let memory = (self.lib.get_memory)(self.ctx.ptr);
             if memory.is_null() {
-                warn!("llama_get_memory returned NULL during warmup — KV cache not cleared");
+                warn!("engine_warmup: llama_get_memory returned NULL — KV cache not cleared");
             } else {
                 (self.lib.memory_clear)(memory, false);
             }
         }
 
-        info!("Warmup complete");
+        info!(elapsed_ms = t.elapsed().as_millis(), "engine_ready");
         Ok(())
     }
 
@@ -299,6 +319,14 @@ impl InferenceEngine {
         // `true` forces a full clear including M-RoPE position metadata; `false` only clears
         // cell occupancy flags and leaves position data intact, which causes the
         // "inconsistent sequence positions" error on models that use M-RoPE (e.g. Qwen).
+        // Truncate prompt for logging — show first 120 chars to aid debugging without flooding logs.
+        let prompt_preview = if prompt.len() > 120 {
+            format!("{}…", &prompt[..120])
+        } else {
+            prompt.to_owned()
+        };
+        tracing::debug!(prompt_chars = prompt.len(), preview = %prompt_preview, "session.new");
+
         unsafe {
             let memory = (self.lib.get_memory)(self.ctx.ptr);
             if memory.is_null() {
@@ -306,7 +334,7 @@ impl InferenceEngine {
                 anyhow::bail!("KV cache clear failed: llama_get_memory returned NULL");
             } else {
                 (self.lib.memory_clear)(memory, true);
-                tracing::info!("engine.kv_cache_cleared");
+                tracing::debug!("kv_cache_cleared");
             }
         }