1use chrono::{Duration, Utc};
2use clap::ValueEnum;
3use ferrum_types::{
4 FerrumError, FerrumObservabilityConfig, FerrumProfileEvent, MemorySnapshot,
5 ObservabilityProfileDetail, ProfileEntrypoint, ProfileError, ProfileEventKind, ProfileStatus,
6 ReplayReference, ResourceAction, ResourceTraceEvent, Result, SamplingParams,
7 DEFAULT_OBSERVABILITY_PROFILE_SAMPLE_RATE, OBSERVABILITY_PROFILE_SCHEMA_VERSION,
8};
9use serde_json::{json, Value};
10use sha2::{Digest, Sha256};
11use std::collections::BTreeMap;
12use std::fs;
13use std::ops::Deref;
14use std::path::{Path, PathBuf};
15use uuid::Uuid;
16
17const SYNTHETIC_MODEL: &str = "synthetic/no-weight";
18const SYNTHETIC_BACKEND: &str = "synthetic";
19
20#[derive(Clone, Copy, Debug, Default, PartialEq, Eq, ValueEnum)]
21pub enum ProfileDetailArg {
22 #[default]
23 Off,
24 Basic,
25 Resource,
26 Latency,
27 Kernel,
28 Debug,
29 Replay,
30 Verify,
31 Full,
32}
33
34impl ProfileDetailArg {
35 pub fn as_str(self) -> &'static str {
36 match self {
37 Self::Off => "off",
38 Self::Basic => "basic",
39 Self::Resource => "resource",
40 Self::Latency => "latency",
41 Self::Kernel => "kernel",
42 Self::Debug => "debug",
43 Self::Replay => "replay",
44 Self::Verify => "verify",
45 Self::Full => "full",
46 }
47 }
48}
49
50impl From<ProfileDetailArg> for ObservabilityProfileDetail {
51 fn from(value: ProfileDetailArg) -> Self {
52 match value {
53 ProfileDetailArg::Off => Self::Off,
54 ProfileDetailArg::Basic => Self::Basic,
55 ProfileDetailArg::Resource => Self::Resource,
56 ProfileDetailArg::Latency => Self::Latency,
57 ProfileDetailArg::Kernel => Self::Kernel,
58 ProfileDetailArg::Debug => Self::Debug,
59 ProfileDetailArg::Replay => Self::Replay,
60 ProfileDetailArg::Verify => Self::Verify,
61 ProfileDetailArg::Full => Self::Full,
62 }
63 }
64}
65
66#[derive(Clone, Debug)]
67pub struct ProductObservabilityConfig {
68 pub core: FerrumObservabilityConfig,
69}
70
71impl Deref for ProductObservabilityConfig {
72 type Target = FerrumObservabilityConfig;
73
74 fn deref(&self) -> &Self::Target {
75 &self.core
76 }
77}
78
79pub struct ActualRunObservation {
80 pub request_id: String,
81 pub duration_us: u64,
82 pub sampling_params: SamplingParams,
83 pub prompt_token_ids: Option<Vec<u32>>,
84 pub prompt_token_count: Option<usize>,
85 pub output_tokens: usize,
86 pub output_token_ids: Vec<u32>,
87 pub chunk_count: usize,
88 pub finish_reason: Option<String>,
89 pub prompt_chars: usize,
90 pub response_chars: usize,
91 pub response_text: String,
92 pub execution_evidence: Option<ferrum_types::InferenceExecutionEvidence>,
93 pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
94 pub memory_stages: Vec<ActualMemoryStageObservation>,
95}
96
97pub struct ActualRunFailureObservation {
98 pub request_id: String,
99 pub duration_us: u64,
100 pub sampling_params: SamplingParams,
101 pub prompt_token_ids: Option<Vec<u32>>,
102 pub prompt_token_count: Option<usize>,
103 pub prompt_chars: usize,
104 pub failure_kind: String,
105 pub error_kind: String,
106 pub error_message: String,
107 pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
108 pub memory_stages: Vec<ActualMemoryStageObservation>,
109}
110
111#[derive(Clone, Debug)]
112pub struct ActualMemoryStageObservation {
113 pub phase: String,
114 pub stage: String,
115 pub duration_us: Option<u64>,
116 pub memory: Option<crate::memory_profile::ProcessMemoryObservation>,
117 pub attributes: BTreeMap<String, Value>,
118}
119
120impl ActualMemoryStageObservation {
121 pub fn new(
122 phase: impl Into<String>,
123 stage: impl Into<String>,
124 duration_us: Option<u64>,
125 memory: Option<crate::memory_profile::ProcessMemoryObservation>,
126 ) -> Self {
127 Self {
128 phase: phase.into(),
129 stage: stage.into(),
130 duration_us,
131 memory,
132 attributes: BTreeMap::new(),
133 }
134 }
135
136 pub fn with_attribute(mut self, key: impl Into<String>, value: Value) -> Self {
137 self.attributes.insert(key.into(), value);
138 self
139 }
140
141 pub fn with_profile_run_status(
142 mut self,
143 executed: bool,
144 status: impl Into<String>,
145 source: impl Into<String>,
146 ) -> Self {
147 self.attributes.extend([
148 ("profile_run_executed".to_string(), json!(executed)),
149 ("profile_run_status".to_string(), json!(status.into())),
150 ("profile_run_source".to_string(), json!(source.into())),
151 ]);
152 self
153 }
154
155 pub fn with_engine_cache_status(mut self, status: &ferrum_types::EngineStatus) -> Self {
156 let memory = &status.memory_usage;
157 let dynamic_capacity_bytes = memory.cache_memory_bytes.saturating_add(memory.free_bytes);
158 self.attributes.extend([
159 (
160 "kv_cache_total_bytes".to_string(),
161 json!(dynamic_capacity_bytes),
162 ),
163 (
164 "kv_cache_used_bytes".to_string(),
165 json!(memory.cache_memory_bytes),
166 ),
167 ("kv_cache_free_bytes".to_string(), json!(memory.free_bytes)),
168 (
169 "cache_memory_bytes".to_string(),
170 json!(memory.cache_memory_bytes),
171 ),
172 (
173 "available_kv_or_state_bytes".to_string(),
174 json!(memory.free_bytes),
175 ),
176 (
177 "resource_total_bytes".to_string(),
178 json!(memory.total_bytes),
179 ),
180 ("resource_used_bytes".to_string(), json!(memory.used_bytes)),
181 ("resource_free_bytes".to_string(), json!(memory.free_bytes)),
182 ]);
183 self
184 }
185}
186
187impl ProductObservabilityConfig {
188 #[allow(clippy::too_many_arguments)]
189 pub fn new(
190 entrypoint: ProfileEntrypoint,
191 model: impl Into<String>,
192 profile_jsonl: Option<&PathBuf>,
193 profile_detail: ProfileDetailArg,
194 memory_profile_jsonl: Option<&PathBuf>,
195 scheduler_trace_jsonl: Option<&PathBuf>,
196 request_dump_dir: Option<&PathBuf>,
197 profile_sample_rate: f64,
198 ) -> Self {
199 Self {
200 core: FerrumObservabilityConfig::new(
201 entrypoint,
202 model,
203 profile_jsonl.cloned(),
204 profile_detail.into(),
205 memory_profile_jsonl.cloned(),
206 scheduler_trace_jsonl.cloned(),
207 request_dump_dir.cloned(),
208 profile_sample_rate,
209 ),
210 }
211 }
212
213 pub fn enabled(&self) -> bool {
214 self.core.enabled()
215 }
216
217 pub fn synthetic_no_weight_enabled(&self) -> bool {
218 self.core.synthetic_no_weight_enabled()
219 }
220
221 pub fn unified_product_profile_enabled(&self) -> bool {
222 self.core.unified_product_profile_enabled()
223 }
224
225 fn validate(&self) -> Result<()> {
226 self.core.validate().map_err(FerrumError::invalid_parameter)
227 }
228}
229
230pub fn default_profile_sample_rate() -> f64 {
231 DEFAULT_OBSERVABILITY_PROFILE_SAMPLE_RATE
232}
233
234pub fn write_synthetic_product_observability(
235 config: &ProductObservabilityConfig,
236) -> Result<Vec<PathBuf>> {
237 config.validate()?;
238 let request_id = format!(
239 "product-obs-{}-{}",
240 entrypoint_label(config.entrypoint),
241 Uuid::new_v4().simple()
242 );
243 let replay_command = replay_command(config);
244 let events = product_events(config, &request_id, &replay_command);
245 let mut written = write_profile_outputs(
246 config,
247 &events,
248 ferrum_bench_core::JsonlJournalOpenMode::Truncate,
249 true,
250 true,
251 true,
252 )?;
253 if let Some(dir) = &config.request_dump_dir {
254 fs_create_dir_all(dir)?;
255 written.extend(write_replay_bundle(
256 dir,
257 config,
258 &request_id,
259 &replay_command,
260 ReplayBundleData {
261 request: request_dump(config, &request_id, &replay_command),
262 prompt_token_ids: Some(vec![101, 202, 303, 404]),
263 prompt_token_count: Some(4),
264 prompt_token_unavailable_reason: None,
265 sampling_params: Some(SamplingParams::greedy()),
266 backend: SYNTHETIC_BACKEND,
267 actual_model_smoke: false,
268 output_token_ids: Some(vec![909, 808]),
269 output_text: Some("synthetic ok"),
270 finish_reason: Some("stop"),
271 failure_kind: None,
272 failure_diagnostics: None,
273 },
274 )?);
275 }
276 Ok(written)
277}
278
279pub fn write_actual_run_observability(
280 config: &ProductObservabilityConfig,
281 observation: &ActualRunObservation,
282) -> Result<Vec<PathBuf>> {
283 if !config.enabled() {
284 return Ok(Vec::new());
285 }
286 config.validate()?;
287 if let Some(timing) = observation
288 .execution_evidence
289 .as_ref()
290 .and_then(|evidence| evidence.engine_token_timing.as_ref())
291 {
292 timing
293 .validate(observation.output_tokens)
294 .map_err(FerrumError::invalid_parameter)?;
295 }
296 let replay_command = replay_command(config);
297 let events = actual_run_events(config, observation, &replay_command);
298 write_actual_run_artifacts(config, &events, observation, &replay_command)
299}
300
301pub fn write_actual_run_failure_observability(
302 config: &ProductObservabilityConfig,
303 observation: &ActualRunFailureObservation,
304) -> Result<Vec<PathBuf>> {
305 if !config.enabled() {
306 return Ok(Vec::new());
307 }
308 config.validate()?;
309 let replay_command = replay_command(config);
310 let events = actual_run_failure_events(config, observation, &replay_command);
311 write_actual_run_failure_artifacts(config, &events, observation, &replay_command)
312}
313
314pub fn write_actual_serve_startup_observability(
315 config: &ProductObservabilityConfig,
316 startup_duration_us: u64,
317 startup_memory: Option<crate::memory_profile::ProcessMemoryObservation>,
318 memory_stages: Vec<ActualMemoryStageObservation>,
319) -> Result<Vec<PathBuf>> {
320 if !config.unified_product_profile_enabled() {
321 return Ok(Vec::new());
322 }
323 config.validate()?;
324 let request_id = format!("serve-startup-{}", Uuid::new_v4().simple());
325 let replay_command = replay_command(config);
326 let events = actual_serve_startup_events(
327 config,
328 &request_id,
329 startup_duration_us,
330 startup_memory.as_ref(),
331 &memory_stages,
332 &replay_command,
333 );
334 write_actual_artifacts(config, &events, &request_id, &replay_command)
335}
336
337pub fn append_actual_serve_memory_stage_observability(
338 config: &ProductObservabilityConfig,
339 stage: ActualMemoryStageObservation,
340) -> Result<Vec<PathBuf>> {
341 if !config.unified_product_profile_enabled() {
342 return Ok(Vec::new());
343 }
344 config.validate()?;
345 let request_id = format!("serve-memory-{}", Uuid::new_v4().simple());
346 let events = actual_memory_stage_events(config, &request_id, &[stage], Utc::now());
347 write_profile_outputs(
348 config,
349 &events,
350 ferrum_bench_core::JsonlJournalOpenMode::Append,
351 true,
352 true,
353 false,
354 )
355}
356
357fn write_actual_run_artifacts(
358 config: &ProductObservabilityConfig,
359 events: &[FerrumProfileEvent],
360 observation: &ActualRunObservation,
361 replay_command: &str,
362) -> Result<Vec<PathBuf>> {
363 let mut written = write_actual_artifacts_with_scheduler(
366 config,
367 events,
368 &observation.request_id,
369 replay_command,
370 false,
371 )?;
372 if let Some(dir) = &config.request_dump_dir {
373 written.extend(write_replay_bundle(
374 dir,
375 config,
376 &observation.request_id,
377 replay_command,
378 ReplayBundleData {
379 request: actual_request_dump(config, &observation.request_id, replay_command),
380 prompt_token_ids: observation.prompt_token_ids.clone(),
381 prompt_token_count: observation.prompt_token_count,
382 prompt_token_unavailable_reason: observation.prompt_token_ids.is_none().then_some(
383 "rendered prompt token ids were unavailable for run one-shot observability",
384 ),
385 sampling_params: Some(observation.sampling_params.clone()),
386 backend: "actual",
387 actual_model_smoke: true,
388 output_token_ids: Some(observation.output_token_ids.clone()),
389 output_text: Some(&observation.response_text),
390 finish_reason: observation.finish_reason.as_deref(),
391 failure_kind: None,
392 failure_diagnostics: None,
393 },
394 )?);
395 }
396 Ok(written)
397}
398
399fn write_actual_run_failure_artifacts(
400 config: &ProductObservabilityConfig,
401 events: &[FerrumProfileEvent],
402 observation: &ActualRunFailureObservation,
403 replay_command: &str,
404) -> Result<Vec<PathBuf>> {
405 let mut written =
406 write_actual_artifacts(config, events, &observation.request_id, replay_command)?;
407 if let Some(dir) = &config.request_dump_dir {
408 written.extend(write_replay_bundle(
409 dir,
410 config,
411 &observation.request_id,
412 replay_command,
413 ReplayBundleData {
414 request: actual_request_dump(config, &observation.request_id, replay_command),
415 prompt_token_ids: observation.prompt_token_ids.clone(),
416 prompt_token_count: observation.prompt_token_count,
417 prompt_token_unavailable_reason: observation.prompt_token_ids.is_none().then_some(
418 "rendered prompt token ids were unavailable for run failure observability",
419 ),
420 sampling_params: Some(observation.sampling_params.clone()),
421 backend: "actual",
422 actual_model_smoke: true,
423 output_token_ids: Some(Vec::new()),
424 output_text: Some(""),
425 finish_reason: Some("error"),
426 failure_kind: Some(observation.failure_kind.as_str()),
427 failure_diagnostics: Some(actual_run_failure_diagnostics(observation)),
428 },
429 )?);
430 }
431 Ok(written)
432}
433
434fn write_actual_artifacts(
435 config: &ProductObservabilityConfig,
436 events: &[FerrumProfileEvent],
437 request_id: &str,
438 replay_command: &str,
439) -> Result<Vec<PathBuf>> {
440 write_actual_artifacts_with_scheduler(config, events, request_id, replay_command, true)
441}
442
443fn write_actual_artifacts_with_scheduler(
444 config: &ProductObservabilityConfig,
445 events: &[FerrumProfileEvent],
446 request_id: &str,
447 replay_command: &str,
448 include_scheduler: bool,
449) -> Result<Vec<PathBuf>> {
450 let mut written = write_profile_outputs(
451 config,
452 events,
453 ferrum_bench_core::JsonlJournalOpenMode::Append,
454 true,
455 true,
456 include_scheduler,
457 )?;
458 if let Some(dir) = &config.request_dump_dir {
459 fs_create_dir_all(dir)?;
460 written.extend(write_replay_bundle(
461 dir,
462 config,
463 request_id,
464 replay_command,
465 ReplayBundleData {
466 request: actual_request_dump(config, request_id, replay_command),
467 prompt_token_ids: None,
468 prompt_token_count: None,
469 prompt_token_unavailable_reason: Some(
470 "startup or non-run request has no rendered prompt token dump in WP9 L0",
471 ),
472 sampling_params: None,
473 backend: "actual",
474 actual_model_smoke: true,
475 output_token_ids: Some(Vec::new()),
476 output_text: None,
477 finish_reason: None,
478 failure_kind: None,
479 failure_diagnostics: None,
480 },
481 )?);
482 }
483 Ok(written)
484}
485
486#[derive(Clone, Copy, Default)]
487struct ProfileOutputRoles {
488 profile: bool,
489 memory: bool,
490 scheduler: bool,
491}
492
493fn add_profile_output_target(
494 targets: &mut BTreeMap<PathBuf, ProfileOutputRoles>,
495 path: Option<&PathBuf>,
496 role: fn(&mut ProfileOutputRoles) -> &mut bool,
497) -> Result<()> {
498 let Some(path) = path else {
499 return Ok(());
500 };
501 let normalized = ferrum_bench_core::normalize_jsonl_path(path).map_err(|error| {
502 FerrumError::io(format!(
503 "normalize observability JSONL path {}: {error}",
504 path.display()
505 ))
506 })?;
507 *role(targets.entry(normalized).or_default()) = true;
508 Ok(())
509}
510
511fn write_profile_outputs(
512 config: &ProductObservabilityConfig,
513 events: &[FerrumProfileEvent],
514 mode: ferrum_bench_core::JsonlJournalOpenMode,
515 include_profile: bool,
516 include_memory: bool,
517 include_scheduler: bool,
518) -> Result<Vec<PathBuf>> {
519 let mut targets = BTreeMap::<PathBuf, ProfileOutputRoles>::new();
520 if include_profile {
521 add_profile_output_target(&mut targets, config.profile_jsonl.as_ref(), |roles| {
522 &mut roles.profile
523 })?;
524 }
525 if include_memory {
526 add_profile_output_target(
527 &mut targets,
528 config.memory_profile_jsonl.as_ref(),
529 |roles| &mut roles.memory,
530 )?;
531 }
532 if include_scheduler {
533 add_profile_output_target(
534 &mut targets,
535 config.scheduler_trace_jsonl.as_ref(),
536 |roles| &mut roles.scheduler,
537 )?;
538 }
539
540 let mut written = Vec::with_capacity(targets.len());
541 for (path, roles) in targets {
542 let selected = events
543 .iter()
544 .filter(|event| {
545 roles.profile
546 || (roles.memory && event.memory.is_some())
547 || (roles.scheduler && event.resource.is_some())
548 })
549 .cloned()
550 .collect::<Vec<_>>();
551 if selected.is_empty() {
552 continue;
553 }
554 write_profile_events(&path, mode, &selected)?;
555 written.push(path);
556 }
557 Ok(written)
558}
559
560fn product_events(
561 config: &ProductObservabilityConfig,
562 request_id: &str,
563 replay_command: &str,
564) -> Vec<FerrumProfileEvent> {
565 let base = Utc::now();
566 let open = resource_event(
567 config,
568 request_id,
569 "request",
570 request_id,
571 "request_slot",
572 "request_open",
573 ResourceAction::RequestOpen,
574 base,
575 None,
576 None,
577 None,
578 Some(1),
579 None,
580 );
581 let reserve = resource_event(
582 config,
583 request_id,
584 "request",
585 request_id,
586 "request_slot",
587 "request_slot_reserve",
588 ResourceAction::Reserve,
589 base + Duration::microseconds(10),
590 Some(1),
591 Some(0),
592 Some(1),
593 Some(1),
594 None,
595 );
596 let commit = resource_event(
597 config,
598 request_id,
599 "request",
600 request_id,
601 "request_slot",
602 "request_slot_commit",
603 ResourceAction::Commit,
604 base + Duration::microseconds(20),
605 Some(1),
606 Some(0),
607 Some(1),
608 Some(1),
609 None,
610 );
611
612 let mut prefill = base_event(
613 config,
614 request_id,
615 "synthetic_prefill",
616 ProfileEventKind::TimedSpan,
617 base + Duration::microseconds(30),
618 );
619 prefill.duration_us = Some(160);
620 prefill.memory = Some(MemorySnapshot {
621 scope: "process".to_string(),
622 backend: Some(SYNTHETIC_BACKEND.to_string()),
623 before_bytes: Some(2048),
624 after_bytes: Some(2304),
625 current_bytes: Some(2304),
626 high_water_bytes: Some(2304),
627 available_bytes: Some(1024 * 1024),
628 });
629 prefill.attributes.extend(common_attrs(config));
630 prefill
631 .attributes
632 .insert("input_tokens".to_string(), json!(8));
633
634 let release = resource_event(
635 config,
636 request_id,
637 "request",
638 request_id,
639 "request_slot",
640 "request_slot_release",
641 ResourceAction::Release,
642 base + Duration::microseconds(180),
643 Some(1),
644 Some(1),
645 Some(0),
646 Some(1),
647 None,
648 );
649
650 let mut close = resource_event(
651 config,
652 request_id,
653 "request",
654 request_id,
655 "request_slot",
656 "request_close",
657 ResourceAction::RequestClose,
658 base + Duration::microseconds(190),
659 None,
660 None,
661 None,
662 Some(1),
663 None,
664 );
665 close.status = if config.profile_detail.diagnostic_only() {
666 ProfileStatus::DiagnosticOnly
667 } else {
668 ProfileStatus::Ok
669 };
670 close.replay = Some(ReplayReference {
671 command: replay_command.to_string(),
672 bundle_dir: config
673 .request_dump_dir
674 .as_ref()
675 .map(|path| path.to_string_lossy().to_string()),
676 });
677 close.attributes.extend(common_attrs(config));
678 close
679 .attributes
680 .insert("response_text".to_string(), json!("synthetic ok"));
681 vec![open, reserve, commit, prefill, release, close]
682}
683
684fn actual_run_events(
685 config: &ProductObservabilityConfig,
686 observation: &ActualRunObservation,
687 replay_command: &str,
688) -> Vec<FerrumProfileEvent> {
689 let base = Utc::now();
690 let shutdown_stage_index = observation
691 .memory_stages
692 .iter()
693 .position(|stage| stage.stage == "shutdown")
694 .unwrap_or(observation.memory_stages.len());
695 let mut events = actual_memory_stage_events(
696 config,
697 &observation.request_id,
698 &observation.memory_stages[..shutdown_stage_index],
699 base,
700 );
701 let open = actual_resource_event(
702 config,
703 &observation.request_id,
704 "request",
705 &observation.request_id,
706 "request_slot",
707 "request_open",
708 ResourceAction::RequestOpen,
709 base,
710 None,
711 None,
712 None,
713 Some(1),
714 None,
715 );
716 let reserve = actual_resource_event(
717 config,
718 &observation.request_id,
719 "request",
720 &observation.request_id,
721 "request_slot",
722 "request_slot_reserve",
723 ResourceAction::Reserve,
724 base + Duration::microseconds(5),
725 Some(1),
726 Some(0),
727 Some(1),
728 Some(1),
729 None,
730 );
731 let commit = actual_resource_event(
732 config,
733 &observation.request_id,
734 "request",
735 &observation.request_id,
736 "request_slot",
737 "request_slot_commit",
738 ResourceAction::Commit,
739 base + Duration::microseconds(10),
740 Some(1),
741 Some(0),
742 Some(1),
743 Some(1),
744 None,
745 );
746
747 let mut generation = actual_base_event(
748 config,
749 &observation.request_id,
750 "actual_run_generation",
751 ProfileEventKind::TimedSpan,
752 base + Duration::microseconds(20),
753 );
754 generation.duration_us = Some(observation.duration_us);
755 attach_process_memory(
756 &mut generation,
757 observation.memory.as_ref(),
758 "first_request_done",
759 );
760 generation.attributes.insert(
761 "output_tokens".to_string(),
762 json!(observation.output_tokens),
763 );
764 generation.attributes.insert(
765 "output_token_count".to_string(),
766 json!(observation.output_tokens),
767 );
768 generation.attributes.insert(
769 "completion_token_count".to_string(),
770 json!(observation.output_tokens),
771 );
772 generation.attributes.insert(
773 "e2e_duration_us".to_string(),
774 json!(observation.duration_us),
775 );
776 if let Some(prompt_token_count) = observation.prompt_token_count {
777 generation
778 .attributes
779 .insert("prompt_token_count".to_string(), json!(prompt_token_count));
780 generation.attributes.insert(
781 "total_token_count".to_string(),
782 json!(prompt_token_count.saturating_add(observation.output_tokens)),
783 );
784 generation.attributes.insert(
785 "token_count_source".to_string(),
786 json!("rendered_prompt_and_generated_tokens"),
787 );
788 } else {
789 generation.attributes.insert(
790 "total_token_count".to_string(),
791 json!(observation.output_tokens),
792 );
793 generation
794 .attributes
795 .insert("token_count_source".to_string(), json!("generated_tokens"));
796 generation.attributes.insert(
797 "prompt_token_unavailable_reason".to_string(),
798 json!("run rendered prompt token count was unavailable"),
799 );
800 }
801 generation
802 .attributes
803 .insert("chunk_count".to_string(), json!(observation.chunk_count));
804 generation.attributes.insert(
805 "finish_reason".to_string(),
806 json!(observation.finish_reason.as_deref().unwrap_or("unknown")),
807 );
808 if let Some(timing) = observation
809 .execution_evidence
810 .as_ref()
811 .and_then(|evidence| evidence.engine_token_timing.as_ref())
812 {
813 generation
814 .attributes
815 .extend(ferrum_types::engine_token_timing_profile_attributes(timing));
816 }
817
818 let release = actual_resource_event(
819 config,
820 &observation.request_id,
821 "request",
822 &observation.request_id,
823 "request_slot",
824 "request_slot_release",
825 ResourceAction::Release,
826 base + Duration::microseconds(30),
827 Some(1),
828 Some(1),
829 Some(0),
830 Some(1),
831 None,
832 );
833
834 let mut close = actual_resource_event(
835 config,
836 &observation.request_id,
837 "request",
838 &observation.request_id,
839 "request_slot",
840 "request_close",
841 ResourceAction::RequestClose,
842 base + Duration::microseconds(40),
843 None,
844 None,
845 None,
846 Some(1),
847 None,
848 );
849 close.replay = Some(ReplayReference {
850 command: replay_command.to_string(),
851 bundle_dir: config
852 .request_dump_dir
853 .as_ref()
854 .map(|path| path.to_string_lossy().to_string()),
855 });
856 close
857 .attributes
858 .insert("prompt_chars".to_string(), json!(observation.prompt_chars));
859 close.attributes.insert(
860 "response_chars".to_string(),
861 json!(observation.response_chars),
862 );
863 events.extend([open, reserve, commit, generation, release, close]);
864 events.extend(actual_memory_stage_events(
865 config,
866 &observation.request_id,
867 &observation.memory_stages[shutdown_stage_index..],
868 base + Duration::microseconds(50),
869 ));
870 events
871}
872
873fn actual_run_failure_events(
874 config: &ProductObservabilityConfig,
875 observation: &ActualRunFailureObservation,
876 replay_command: &str,
877) -> Vec<FerrumProfileEvent> {
878 let base = Utc::now();
879 let shutdown_stage_index = observation
880 .memory_stages
881 .iter()
882 .position(|stage| stage.stage == "shutdown")
883 .unwrap_or(observation.memory_stages.len());
884 let mut events = actual_memory_stage_events(
885 config,
886 &observation.request_id,
887 &observation.memory_stages[..shutdown_stage_index],
888 base,
889 );
890 let open = actual_resource_event(
891 config,
892 &observation.request_id,
893 "request",
894 &observation.request_id,
895 "request_slot",
896 "request_open",
897 ResourceAction::RequestOpen,
898 base,
899 None,
900 None,
901 None,
902 Some(1),
903 None,
904 );
905 let reserve = actual_resource_event(
906 config,
907 &observation.request_id,
908 "request",
909 &observation.request_id,
910 "request_slot",
911 "request_slot_reserve",
912 ResourceAction::Reserve,
913 base + Duration::microseconds(5),
914 Some(1),
915 Some(0),
916 Some(1),
917 Some(1),
918 None,
919 );
920 let commit = actual_resource_event(
921 config,
922 &observation.request_id,
923 "request",
924 &observation.request_id,
925 "request_slot",
926 "request_slot_commit",
927 ResourceAction::Commit,
928 base + Duration::microseconds(10),
929 Some(1),
930 Some(0),
931 Some(1),
932 Some(1),
933 None,
934 );
935
936 let mut failure = actual_base_event(
937 config,
938 &observation.request_id,
939 "actual_run_generation_failed",
940 ProfileEventKind::TimedSpan,
941 base + Duration::microseconds(20),
942 );
943 failure.status = ProfileStatus::Failure;
944 failure.duration_us = Some(observation.duration_us);
945 failure.error = Some(ProfileError {
946 kind: observation.error_kind.clone(),
947 message: observation.error_message.clone(),
948 blocking: false,
949 });
950 failure.replay = Some(ReplayReference {
951 command: replay_command.to_string(),
952 bundle_dir: config
953 .request_dump_dir
954 .as_ref()
955 .map(|path| path.to_string_lossy().to_string()),
956 });
957 attach_process_memory(
958 &mut failure,
959 observation.memory.as_ref(),
960 "first_request_failed",
961 );
962 failure
963 .attributes
964 .insert("terminal_failure_event".to_string(), json!(true));
965 failure
966 .attributes
967 .insert("prompt_chars".to_string(), json!(observation.prompt_chars));
968
969 let release = actual_resource_event(
970 config,
971 &observation.request_id,
972 "request",
973 &observation.request_id,
974 "request_slot",
975 "request_slot_release",
976 ResourceAction::Release,
977 base + Duration::microseconds(30),
978 Some(1),
979 Some(1),
980 Some(0),
981 Some(1),
982 None,
983 );
984
985 let mut close = actual_resource_event(
986 config,
987 &observation.request_id,
988 "request",
989 &observation.request_id,
990 "request_slot",
991 "request_close",
992 ResourceAction::RequestClose,
993 base + Duration::microseconds(40),
994 None,
995 None,
996 None,
997 Some(1),
998 None,
999 );
1000 close.replay = Some(ReplayReference {
1001 command: replay_command.to_string(),
1002 bundle_dir: config
1003 .request_dump_dir
1004 .as_ref()
1005 .map(|path| path.to_string_lossy().to_string()),
1006 });
1007 events.extend([open, reserve, commit, failure, release, close]);
1008 events.extend(actual_memory_stage_events(
1009 config,
1010 &observation.request_id,
1011 &observation.memory_stages[shutdown_stage_index..],
1012 base + Duration::microseconds(50),
1013 ));
1014 events
1015}
1016
1017fn actual_memory_stage_events(
1018 config: &ProductObservabilityConfig,
1019 request_id: &str,
1020 stages: &[ActualMemoryStageObservation],
1021 base: chrono::DateTime<Utc>,
1022) -> Vec<FerrumProfileEvent> {
1023 stages
1024 .iter()
1025 .enumerate()
1026 .map(|(index, stage)| {
1027 let mut event = actual_base_event(
1028 config,
1029 request_id,
1030 &stage.phase,
1031 ProfileEventKind::Memory,
1032 base + Duration::microseconds(index as i64),
1033 );
1034 event.duration_us = stage.duration_us;
1035 attach_process_memory(&mut event, stage.memory.as_ref(), &stage.stage);
1036 event.attributes.extend(stage.attributes.clone());
1037 event
1038 })
1039 .collect()
1040}
1041
1042fn actual_serve_startup_events(
1043 config: &ProductObservabilityConfig,
1044 request_id: &str,
1045 startup_duration_us: u64,
1046 startup_memory: Option<&crate::memory_profile::ProcessMemoryObservation>,
1047 memory_stages: &[ActualMemoryStageObservation],
1048 replay_command: &str,
1049) -> Vec<FerrumProfileEvent> {
1050 let base = Utc::now();
1051 let post_model_loaded_index = memory_stages
1052 .iter()
1053 .position(|stage| matches!(stage.stage.as_str(), "profile_run_done" | "cache_allocated"))
1054 .unwrap_or(memory_stages.len());
1055 let mut events = actual_memory_stage_events(
1056 config,
1057 request_id,
1058 &memory_stages[..post_model_loaded_index],
1059 base,
1060 );
1061 let open = actual_resource_event(
1062 config,
1063 request_id,
1064 "server",
1065 request_id,
1066 "startup_slot",
1067 "server_startup_open",
1068 ResourceAction::RequestOpen,
1069 base,
1070 None,
1071 None,
1072 None,
1073 Some(1),
1074 None,
1075 );
1076 let reserve = actual_resource_event(
1077 config,
1078 request_id,
1079 "server",
1080 request_id,
1081 "startup_slot",
1082 "server_startup_reserve",
1083 ResourceAction::Reserve,
1084 base + Duration::microseconds(5),
1085 Some(1),
1086 Some(0),
1087 Some(1),
1088 Some(1),
1089 None,
1090 );
1091 let commit = actual_resource_event(
1092 config,
1093 request_id,
1094 "server",
1095 request_id,
1096 "startup_slot",
1097 "server_startup_commit",
1098 ResourceAction::Commit,
1099 base + Duration::microseconds(10),
1100 Some(1),
1101 Some(0),
1102 Some(1),
1103 Some(1),
1104 None,
1105 );
1106 let mut startup = actual_base_event(
1107 config,
1108 request_id,
1109 "actual_serve_startup",
1110 ProfileEventKind::TimedSpan,
1111 base + Duration::microseconds(20),
1112 );
1113 startup.duration_us = Some(startup_duration_us);
1114 attach_process_memory(&mut startup, startup_memory, "model_loaded");
1115 events.extend([open, reserve, commit, startup]);
1116 events.extend(actual_memory_stage_events(
1117 config,
1118 request_id,
1119 &memory_stages[post_model_loaded_index..],
1120 base + Duration::microseconds(21),
1121 ));
1122
1123 let release = actual_resource_event(
1124 config,
1125 request_id,
1126 "server",
1127 request_id,
1128 "startup_slot",
1129 "server_startup_release",
1130 ResourceAction::Release,
1131 base + Duration::microseconds(30),
1132 Some(1),
1133 Some(1),
1134 Some(0),
1135 Some(1),
1136 None,
1137 );
1138 let mut ready = actual_resource_event(
1139 config,
1140 request_id,
1141 "server",
1142 request_id,
1143 "startup_slot",
1144 "server_ready_for_requests",
1145 ResourceAction::RequestClose,
1146 base + Duration::microseconds(40),
1147 None,
1148 None,
1149 None,
1150 Some(1),
1151 None,
1152 );
1153 ready.replay = Some(ReplayReference {
1154 command: replay_command.to_string(),
1155 bundle_dir: config
1156 .request_dump_dir
1157 .as_ref()
1158 .map(|path| path.to_string_lossy().to_string()),
1159 });
1160 events.extend([release, ready]);
1161 events
1162}
1163
1164fn base_event(
1165 config: &ProductObservabilityConfig,
1166 request_id: &str,
1167 phase: &str,
1168 event_kind: ProfileEventKind,
1169 timestamp: chrono::DateTime<Utc>,
1170) -> FerrumProfileEvent {
1171 FerrumProfileEvent {
1172 schema_version: OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1173 ts_unix_nanos: timestamp
1174 .timestamp_nanos_opt()
1175 .unwrap_or_else(|| timestamp.timestamp_micros() * 1_000),
1176 event_id: format!(
1177 "evt-product-{}-{phase}",
1178 entrypoint_label(config.entrypoint)
1179 ),
1180 request_id: request_id.to_string(),
1181 correlation_id: Some(format!(
1182 "corr-product-{}",
1183 entrypoint_label(config.entrypoint)
1184 )),
1185 entrypoint: config.entrypoint,
1186 backend: SYNTHETIC_BACKEND.to_string(),
1187 runtime_preset_hash: runtime_preset_hash(config),
1188 phase: phase.to_string(),
1189 event_kind,
1190 timestamp,
1191 status: ProfileStatus::Ok,
1192 model: Some(config.model.clone()),
1193 duration_us: None,
1194 memory: None,
1195 resource: None,
1196 error: None,
1197 replay: None,
1198 shape: default_event_shape(),
1199 backend_detail: None,
1200 attributes: common_attrs(config),
1201 }
1202}
1203
1204fn actual_base_event(
1205 config: &ProductObservabilityConfig,
1206 request_id: &str,
1207 phase: &str,
1208 event_kind: ProfileEventKind,
1209 timestamp: chrono::DateTime<Utc>,
1210) -> FerrumProfileEvent {
1211 let mut event = base_event(config, request_id, phase, event_kind, timestamp);
1212 event.backend = "actual".to_string();
1213 event.attributes = actual_attrs(config);
1214 event.attributes.insert(
1215 "execution_request_id".to_string(),
1216 json!(format!("request.product.{request_id}")),
1217 );
1218 event
1219}
1220
1221fn runtime_preset_hash(config: &ProductObservabilityConfig) -> String {
1222 let mut hasher = Sha256::new();
1223 hasher.update(config.entrypoint.as_str().as_bytes());
1224 hasher.update(b"\0");
1225 hasher.update(config.model.as_bytes());
1226 hasher.update(b"\0");
1227 hasher.update(config.profile_detail.as_str().as_bytes());
1228 hasher.update(b"\0");
1229 hasher.update(config.profile_sample_rate.to_string().as_bytes());
1230 format!("sha256:{:x}", hasher.finalize())
1231}
1232
1233fn default_event_shape() -> BTreeMap<String, Value> {
1234 BTreeMap::from([("batch_size".to_string(), json!(1))])
1235}
1236
1237#[allow(clippy::too_many_arguments)]
1238fn resource_event(
1239 config: &ProductObservabilityConfig,
1240 request_id: &str,
1241 owner_kind: &str,
1242 owner_id: &str,
1243 resource_kind: &str,
1244 phase: &str,
1245 action: ResourceAction,
1246 timestamp: chrono::DateTime<Utc>,
1247 amount: Option<i64>,
1248 before: Option<i64>,
1249 after: Option<i64>,
1250 capacity: Option<i64>,
1251 reason: Option<&str>,
1252) -> FerrumProfileEvent {
1253 let mut event = base_event(
1254 config,
1255 request_id,
1256 phase,
1257 ProfileEventKind::Resource,
1258 timestamp,
1259 );
1260 event.resource = Some(ResourceTraceEvent {
1261 owner_kind: owner_kind.to_string(),
1262 owner_id: owner_id.to_string(),
1263 resource_kind: resource_kind.to_string(),
1264 action,
1265 amount,
1266 before,
1267 after,
1268 capacity,
1269 underflow_amount: match (action, amount, before) {
1270 (ResourceAction::Release | ResourceAction::Rollback, Some(amount), Some(before))
1271 if amount > before =>
1272 {
1273 Some(amount.saturating_sub(before))
1274 }
1275 _ => None,
1276 },
1277 reason: reason.map(str::to_string),
1278 error_kind: None,
1279 message: None,
1280 resource_error_kind: None,
1281 });
1282 event
1283}
1284
1285#[allow(clippy::too_many_arguments)]
1286fn actual_resource_event(
1287 config: &ProductObservabilityConfig,
1288 request_id: &str,
1289 owner_kind: &str,
1290 owner_id: &str,
1291 resource_kind: &str,
1292 phase: &str,
1293 action: ResourceAction,
1294 timestamp: chrono::DateTime<Utc>,
1295 amount: Option<i64>,
1296 before: Option<i64>,
1297 after: Option<i64>,
1298 capacity: Option<i64>,
1299 reason: Option<&str>,
1300) -> FerrumProfileEvent {
1301 let mut event = resource_event(
1302 config,
1303 request_id,
1304 owner_kind,
1305 owner_id,
1306 resource_kind,
1307 phase,
1308 action,
1309 timestamp,
1310 amount,
1311 before,
1312 after,
1313 capacity,
1314 reason,
1315 );
1316 event.backend = "actual".to_string();
1317 event.attributes = actual_attrs(config);
1318 event
1319}
1320
1321fn attach_process_memory(
1322 event: &mut FerrumProfileEvent,
1323 observation: Option<&crate::memory_profile::ProcessMemoryObservation>,
1324 stage: &str,
1325) {
1326 if let Some(observation) = observation {
1327 event.memory = Some(observation.to_snapshot("process", Some("actual")));
1328 event
1329 .attributes
1330 .insert("memory_measurement".to_string(), json!("process_rss"));
1331 event
1332 .attributes
1333 .insert("memory_stage".to_string(), json!(stage));
1334 event.attributes.insert(
1335 "process_memory_source".to_string(),
1336 json!(observation.source),
1337 );
1338 } else {
1339 event.memory = Some(MemorySnapshot {
1340 scope: "process".to_string(),
1341 backend: Some("actual".to_string()),
1342 before_bytes: Some(0),
1343 after_bytes: Some(0),
1344 current_bytes: Some(0),
1345 high_water_bytes: Some(0),
1346 available_bytes: None,
1347 });
1348 event
1349 .attributes
1350 .insert("memory_measurement".to_string(), json!("not_collected"));
1351 event
1352 .attributes
1353 .insert("memory_stage".to_string(), json!(stage));
1354 }
1355}
1356
1357fn common_attrs(config: &ProductObservabilityConfig) -> BTreeMap<String, Value> {
1358 BTreeMap::from([
1359 (
1360 "profile_detail".to_string(),
1361 json!(config.profile_detail.as_str()),
1362 ),
1363 (
1364 "profile_sample_rate".to_string(),
1365 json!(config.profile_sample_rate),
1366 ),
1367 (
1368 "diagnostic_only".to_string(),
1369 json!(config.profile_detail.diagnostic_only()),
1370 ),
1371 ("l0_only".to_string(), json!(true)),
1372 ])
1373}
1374
1375fn actual_attrs(config: &ProductObservabilityConfig) -> BTreeMap<String, Value> {
1376 BTreeMap::from([
1377 (
1378 "profile_detail".to_string(),
1379 json!(config.profile_detail.as_str()),
1380 ),
1381 (
1382 "profile_sample_rate".to_string(),
1383 json!(config.profile_sample_rate),
1384 ),
1385 (
1386 "diagnostic_only".to_string(),
1387 json!(config.profile_detail.diagnostic_only()),
1388 ),
1389 ("l0_only".to_string(), json!(false)),
1390 ("actual_model_smoke".to_string(), json!(true)),
1391 ])
1392}
1393
1394struct ReplayBundleData<'a> {
1395 request: serde_json::Value,
1396 prompt_token_ids: Option<Vec<u32>>,
1397 prompt_token_count: Option<usize>,
1398 prompt_token_unavailable_reason: Option<&'a str>,
1399 sampling_params: Option<SamplingParams>,
1400 backend: &'a str,
1401 actual_model_smoke: bool,
1402 output_token_ids: Option<Vec<u32>>,
1403 output_text: Option<&'a str>,
1404 finish_reason: Option<&'a str>,
1405 failure_kind: Option<&'a str>,
1406 failure_diagnostics: Option<serde_json::Value>,
1407}
1408
1409fn write_replay_bundle(
1410 root: &Path,
1411 config: &ProductObservabilityConfig,
1412 request_id: &str,
1413 replay_command: &str,
1414 data: ReplayBundleData<'_>,
1415) -> Result<Vec<PathBuf>> {
1416 fs_create_dir_all(root)?;
1417 let bundle_dir = root.join(request_id);
1418 fs_create_dir_all(&bundle_dir)?;
1419 let mut written = Vec::new();
1420
1421 let request_path = root.join("request.json");
1422 let replay_path = root.join("replay_command.txt");
1423 write_json(&request_path, &data.request)?;
1424 fs_write(&replay_path, format!("{replay_command}\n"))?;
1425 written.push(request_path);
1426 written.push(replay_path);
1427
1428 let prompt_token_count = data
1429 .prompt_token_count
1430 .or_else(|| data.prompt_token_ids.as_ref().map(Vec::len));
1431 let output_token_count = data.output_token_ids.as_ref().map(Vec::len).unwrap_or(0);
1432 let prompt_tokens = json!({
1433 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1434 "request_id": request_id,
1435 "model": config.model,
1436 "tokenizer_or_model": config.model,
1437 "token_ids": data.prompt_token_ids,
1438 "token_count": prompt_token_count,
1439 "unavailable_reason": data.prompt_token_unavailable_reason,
1440 "sanitized": true
1441 });
1442 let output_text = data.output_text.unwrap_or("");
1443 let sampling_unavailable_reason = if data.sampling_params.is_some() {
1444 Value::Null
1445 } else {
1446 json!("sampling params unavailable for this replay bundle kind in WP9 L0")
1447 };
1448 let output_text_body = if data.actual_model_smoke && config.model != SYNTHETIC_MODEL {
1449 format!(
1450 "[redacted actual output]\nsha256={}\nchars={}\n",
1451 sha256_hex(output_text.as_bytes()),
1452 output_text.chars().count()
1453 )
1454 } else {
1455 format!("{output_text}\n")
1456 };
1457 let output_scan = bad_output_scan(
1458 request_id,
1459 output_text,
1460 data.failure_kind,
1461 output_text_body.as_bytes(),
1462 );
1463 let engine_replay_args = engine_replay_command_args(&bundle_dir);
1464 let engine_replay_command = replay_command_from_args(&engine_replay_args);
1465 let files = [
1466 ("request.json", data.request),
1467 ("prompt_token_ids.json", prompt_tokens),
1468 (
1469 "sampling_params.json",
1470 json!({
1471 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1472 "request_id": request_id,
1473 "sampling_params": data.sampling_params,
1474 "unavailable_reason": sampling_unavailable_reason
1475 }),
1476 ),
1477 (
1478 "runtime_effective_config.json",
1479 json!({
1480 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1481 "request_id": request_id,
1482 "entrypoint": entrypoint_label(config.entrypoint),
1483 "profile_detail": config.profile_detail.as_str(),
1484 "profile_sample_rate": config.profile_sample_rate,
1485 "profile_jsonl": config.profile_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1486 "memory_profile_jsonl": config.memory_profile_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1487 "scheduler_trace_jsonl": config.scheduler_trace_jsonl.as_ref().map(|path| path.to_string_lossy().to_string()),
1488 "request_dump_dir": Some(root.to_string_lossy().to_string()),
1489 "sanitized": true
1490 }),
1491 ),
1492 (
1493 "backend_selection.json",
1494 json!({
1495 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1496 "request_id": request_id,
1497 "backend": data.backend,
1498 "model": config.model,
1499 "actual_model_smoke": data.actual_model_smoke
1500 }),
1501 ),
1502 (
1503 "output_token_ids.json",
1504 json!({
1505 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1506 "request_id": request_id,
1507 "token_ids": data.output_token_ids.unwrap_or_default(),
1508 "token_count": output_token_count,
1509 "finish_reason": data.finish_reason
1510 }),
1511 ),
1512 ("bad_output_scan.json", output_scan),
1513 (
1514 "replay.command.json",
1515 json!({
1516 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1517 "request_id": request_id,
1518 "entrypoint": entrypoint_label(config.entrypoint),
1519 "command": replay_command,
1520 "argv": replay_command_args(config),
1521 "bundle_dir": bundle_dir.to_string_lossy(),
1522 "engine_replay": {
1523 "mode": "bundle_offline",
1524 "requires_http_server": false,
1525 "command": engine_replay_command,
1526 "argv": engine_replay_args
1527 },
1528 "sanitized": true
1529 }),
1530 ),
1531 ];
1532 for (name, value) in files {
1533 let path = bundle_dir.join(name);
1534 write_json(&path, &value)?;
1535 written.push(path);
1536 }
1537 if let Some(diagnostics) = data.failure_diagnostics {
1538 let path = bundle_dir.join("failure_diagnostics.json");
1539 write_json(&path, &diagnostics)?;
1540 written.push(path);
1541 }
1542 let output_text_path = bundle_dir.join("output_text.txt");
1543 fs_write(&output_text_path, output_text_body)?;
1544 written.push(output_text_path);
1545 Ok(written)
1546}
1547
1548fn actual_run_failure_diagnostics(observation: &ActualRunFailureObservation) -> serde_json::Value {
1549 if resource_failure_kind(&observation.failure_kind) {
1550 return actual_run_resource_failure_diagnostics(observation);
1551 }
1552 json!({
1553 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1554 "request_id": observation.request_id,
1555 "failure_kind": observation.failure_kind,
1556 "first_failure_event": {
1557 "phase": "actual_run_generation_failed",
1558 "error_kind": observation.error_kind,
1559 "message": observation.error_message
1560 },
1561 "nearest_request_id": observation.request_id,
1562 "log_excerpt": observation.error_message
1563 })
1564}
1565
1566fn actual_run_resource_failure_diagnostics(
1567 observation: &ActualRunFailureObservation,
1568) -> serde_json::Value {
1569 let memory_current = observation
1570 .memory
1571 .as_ref()
1572 .map(|memory| memory.current_bytes as i64)
1573 .unwrap_or(0)
1574 .max(0);
1575 let memory_high_water = observation
1576 .memory
1577 .as_ref()
1578 .map(|memory| memory.high_water_bytes as i64)
1579 .unwrap_or(memory_current);
1580 let resource_kind = resource_kind_for_failure(&observation.failure_kind);
1581 let needed = if resource_kind == "device_memory" {
1582 memory_current.saturating_add(1).max(1)
1583 } else {
1584 observation
1585 .prompt_token_count
1586 .and_then(|tokens| i64::try_from(tokens).ok())
1587 .unwrap_or(1)
1588 .max(1)
1589 };
1590 let capacity = if resource_kind == "device_memory" {
1591 memory_high_water.max(memory_current)
1592 } else {
1593 0
1594 };
1595 json!({
1596 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1597 "request_id": observation.request_id,
1598 "failure_kind": observation.failure_kind,
1599 "first_failure_event": {
1600 "phase": "actual_run_generation_failed",
1601 "error_kind": observation.error_kind,
1602 "message": observation.error_message
1603 },
1604 "nearest_request_id": observation.request_id,
1605 "log_excerpt": observation.error_message,
1606 "capacity": {
1607 "resource_kind": resource_kind,
1608 "needed": needed,
1609 "available": 0,
1610 "capacity": capacity,
1611 "reason": observation.error_message
1612 },
1613 "nearest_resource_event": {
1614 "owner_kind": "request",
1615 "owner_id": observation.request_id,
1616 "resource_kind": resource_kind,
1617 "action": "reject",
1618 "amount": needed,
1619 "before": 0,
1620 "after": 0,
1621 "capacity": capacity,
1622 "reason": observation.error_message
1623 },
1624 "nearest_memory_snapshot": {
1625 "scope": "actual_run_failure",
1626 "backend": "process",
1627 "current_bytes": memory_current,
1628 "high_water_bytes": memory_high_water.max(memory_current),
1629 "source": observation.memory.as_ref().map(|memory| memory.source).unwrap_or("not_collected")
1630 }
1631 })
1632}
1633
1634fn resource_failure_kind(failure_kind: &str) -> bool {
1635 matches!(
1636 failure_kind,
1637 "oom" | "prevented_oom" | "admission" | "admission_reject" | "oom_admission"
1638 )
1639}
1640
1641fn resource_kind_for_failure(failure_kind: &str) -> &'static str {
1642 match failure_kind {
1643 "oom" | "prevented_oom" => "device_memory",
1644 _ => "admission_capacity",
1645 }
1646}
1647
1648fn bad_output_scan(
1649 request_id: &str,
1650 text: &str,
1651 failure_kind: Option<&str>,
1652 output_artifact_bytes: &[u8],
1653) -> serde_json::Value {
1654 let mut reasons = Vec::new();
1655 let mut first_span: Option<serde_json::Value> = None;
1656 for (needle, reason) in [
1657 ("<unk>", "reserved_token"),
1658 ("[PAD", "reserved_token"),
1659 ("<pad>", "reserved_token"),
1660 ("<|endoftext|>", "reserved_token"),
1661 ("<|im_start|>", "reserved_token"),
1662 ("<|im_end|>", "reserved_token"),
1663 ("<|reserved_special_token", "reserved_token"),
1664 ] {
1665 if let Some(index) = text.find(needle) {
1666 reasons.push(reason);
1667 first_span.get_or_insert_with(|| {
1668 json!({
1669 "byte_start": index,
1670 "byte_end": index + needle.len(),
1671 "text": needle,
1672 "reason": reason
1673 })
1674 });
1675 }
1676 }
1677 if let Some(index) = first_mojibake_index(text) {
1678 reasons.push("mojibake");
1679 first_span.get_or_insert_with(|| {
1680 json!({
1681 "byte_start": index,
1682 "byte_end": index + 1,
1683 "reason": "mojibake"
1684 })
1685 });
1686 }
1687 reasons.sort_unstable();
1688 reasons.dedup();
1689 let bad_output = !reasons.is_empty();
1690 json!({
1691 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1692 "request_id": request_id,
1693 "bad_output": bad_output,
1694 "bad_text_count": if bad_output { 1 } else { 0 },
1695 "reasons": reasons,
1696 "first_bad_text_span": first_span,
1697 "failure_kind": failure_kind,
1698 "output_chars": text.chars().count(),
1699 "classified_output_sha256": sha256_hex(text.as_bytes()),
1700 "output_sha256": sha256_hex(output_artifact_bytes)
1701 })
1702}
1703
1704fn first_mojibake_index(text: &str) -> Option<usize> {
1705 ["\u{00c3}\u{00a9}", "\u{00c2}\u{00a9}", "\u{00e2}\u{20ac}"]
1706 .iter()
1707 .filter_map(|needle| text.find(needle))
1708 .min()
1709}
1710
1711fn sha256_hex(bytes: &[u8]) -> String {
1712 let mut hasher = Sha256::new();
1713 hasher.update(bytes);
1714 format!("{:x}", hasher.finalize())
1715}
1716
1717fn request_dump(
1718 config: &ProductObservabilityConfig,
1719 request_id: &str,
1720 replay_command: &str,
1721) -> serde_json::Value {
1722 let entrypoint = entrypoint_label(config.entrypoint);
1723 match config.entrypoint {
1724 ProfileEntrypoint::Run => json!({
1725 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1726 "entrypoint": entrypoint,
1727 "request_id": request_id,
1728 "model": config.model,
1729 "backend": SYNTHETIC_BACKEND,
1730 "profile_detail": config.profile_detail.as_str(),
1731 "profile_sample_rate": config.profile_sample_rate,
1732 "l0_only": true,
1733 "sanitized": true,
1734 "prompt": "product observability wiring",
1735 "replay_command": replay_command
1736 }),
1737 ProfileEntrypoint::Serve => json!({
1738 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1739 "entrypoint": entrypoint,
1740 "request_id": request_id,
1741 "model": config.model,
1742 "backend": SYNTHETIC_BACKEND,
1743 "profile_detail": config.profile_detail.as_str(),
1744 "profile_sample_rate": config.profile_sample_rate,
1745 "l0_only": true,
1746 "sanitized": true,
1747 "http": {
1748 "method": "POST",
1749 "path": "/v1/chat/completions",
1750 "body": {
1751 "model": config.model,
1752 "messages": [{"role": "user", "content": "product observability wiring"}],
1753 "stream": false
1754 }
1755 },
1756 "replay_command": replay_command
1757 }),
1758 other => json!({
1759 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1760 "entrypoint": entrypoint_label(other),
1761 "request_id": request_id,
1762 "model": config.model,
1763 "backend": SYNTHETIC_BACKEND,
1764 "profile_detail": config.profile_detail.as_str(),
1765 "profile_sample_rate": config.profile_sample_rate,
1766 "l0_only": true,
1767 "sanitized": true,
1768 "replay_command": replay_command
1769 }),
1770 }
1771}
1772
1773fn actual_request_dump(
1774 config: &ProductObservabilityConfig,
1775 request_id: &str,
1776 replay_command: &str,
1777) -> serde_json::Value {
1778 json!({
1779 "schema_version": OBSERVABILITY_PROFILE_SCHEMA_VERSION,
1780 "entrypoint": entrypoint_label(config.entrypoint),
1781 "request_id": request_id,
1782 "model": config.model,
1783 "backend": "actual",
1784 "profile_detail": config.profile_detail.as_str(),
1785 "profile_sample_rate": config.profile_sample_rate,
1786 "l0_only": false,
1787 "actual_model_smoke": true,
1788 "sanitized": true,
1789 "replay_command": replay_command
1790 })
1791}
1792
1793fn replay_command(config: &ProductObservabilityConfig) -> String {
1794 replay_command_from_args(&replay_command_args(config))
1795}
1796
1797fn replay_command_from_args(args: &[String]) -> String {
1798 args.iter()
1799 .map(|part| shell_quote(part))
1800 .collect::<Vec<_>>()
1801 .join(" ")
1802}
1803
1804fn replay_command_args(config: &ProductObservabilityConfig) -> Vec<String> {
1805 let mut parts = vec![
1806 "cargo".to_string(),
1807 "run".to_string(),
1808 "-p".to_string(),
1809 "ferrum-cli".to_string(),
1810 "--".to_string(),
1811 entrypoint_label(config.entrypoint).to_string(),
1812 SYNTHETIC_MODEL.to_string(),
1813 "--profile-detail".to_string(),
1814 config.profile_detail.as_str().to_string(),
1815 "--profile-sample-rate".to_string(),
1816 config.profile_sample_rate.to_string(),
1817 ];
1818 push_path_arg(&mut parts, "--profile-jsonl", config.profile_jsonl.as_ref());
1819 push_path_arg(
1820 &mut parts,
1821 "--memory-profile-jsonl",
1822 config.memory_profile_jsonl.as_ref(),
1823 );
1824 push_path_arg(
1825 &mut parts,
1826 "--scheduler-trace-jsonl",
1827 config.scheduler_trace_jsonl.as_ref(),
1828 );
1829 push_path_arg(
1830 &mut parts,
1831 "--request-dump-dir",
1832 config.request_dump_dir.as_ref(),
1833 );
1834 parts
1835}
1836
1837fn engine_replay_command_args(bundle_dir: &Path) -> Vec<String> {
1838 vec![
1839 "cargo".to_string(),
1840 "run".to_string(),
1841 "-p".to_string(),
1842 "ferrum-cli".to_string(),
1843 "--".to_string(),
1844 "replay-bundle".to_string(),
1845 bundle_dir.to_string_lossy().to_string(),
1846 "--out".to_string(),
1847 bundle_dir
1848 .join("engine_replay")
1849 .to_string_lossy()
1850 .to_string(),
1851 "--json".to_string(),
1852 ]
1853}
1854
1855fn push_path_arg(parts: &mut Vec<String>, flag: &str, path: Option<&PathBuf>) {
1856 if let Some(path) = path {
1857 parts.push(flag.to_string());
1858 parts.push(path.to_string_lossy().to_string());
1859 }
1860}
1861
1862#[cfg(test)]
1863fn write_profile_jsonl(path: &Path, events: &[FerrumProfileEvent]) -> Result<()> {
1864 write_profile_events(
1865 path,
1866 ferrum_bench_core::JsonlJournalOpenMode::Truncate,
1867 events,
1868 )
1869}
1870
1871#[cfg(test)]
1872fn append_profile_jsonl(path: &Path, events: &[FerrumProfileEvent]) -> Result<()> {
1873 write_profile_events(
1874 path,
1875 ferrum_bench_core::JsonlJournalOpenMode::Append,
1876 events,
1877 )
1878}
1879
1880fn write_profile_events(
1881 path: &Path,
1882 mode: ferrum_bench_core::JsonlJournalOpenMode,
1883 events: &[FerrumProfileEvent],
1884) -> Result<()> {
1885 if events.is_empty() {
1886 return Err(FerrumError::internal("profile event set must be non-empty"));
1887 }
1888 for event in events {
1889 event.validate().map_err(|err| {
1890 FerrumError::internal(format!("invalid product observability event: {err}"))
1891 })?;
1892 }
1893 ferrum_bench_core::write_jsonl_records(path, mode, events)
1894 .map_err(|error| FerrumError::io(error.to_string()))
1895}
1896
1897fn write_json(path: &Path, value: &serde_json::Value) -> Result<()> {
1898 let body = serde_json::to_string_pretty(value)
1899 .map_err(|err| FerrumError::serialization(format!("failed to serialize JSON: {err}")))?;
1900 fs_write(path, format!("{body}\n"))
1901}
1902
1903fn fs_create_dir_all(path: &Path) -> Result<()> {
1904 fs::create_dir_all(path)
1905 .map_err(|err| FerrumError::io(format!("failed to create {}: {err}", path.display())))
1906}
1907
1908fn fs_write(path: &Path, content: impl AsRef<[u8]>) -> Result<()> {
1909 if let Some(parent) = path.parent() {
1910 fs_create_dir_all(parent)?;
1911 }
1912 fs::write(path, content)
1913 .map_err(|err| FerrumError::io(format!("failed to write {}: {err}", path.display())))
1914}
1915
1916fn entrypoint_label(entrypoint: ProfileEntrypoint) -> &'static str {
1917 match entrypoint {
1918 ProfileEntrypoint::Run => "run",
1919 ProfileEntrypoint::Serve => "serve",
1920 ProfileEntrypoint::BenchServe => "bench_serve",
1921 ProfileEntrypoint::Synthetic => "synthetic",
1922 }
1923}
1924
1925fn shell_quote(value: &str) -> String {
1926 if value
1927 .chars()
1928 .all(|ch| ch.is_ascii_alphanumeric() || "-_./:".contains(ch))
1929 {
1930 return value.to_string();
1931 }
1932 format!("'{}'", value.replace('\'', "'\\''"))
1933}
1934
1935#[cfg(test)]
1936mod tests {
1937 use super::*;
1938
1939 #[test]
1940 fn engine_cache_observation_does_not_report_static_weights_as_kv() {
1941 let status = ferrum_types::EngineStatus {
1942 is_ready: true,
1943 loaded_models: vec![ferrum_types::ModelId::from("test-model")],
1944 active_requests: 0,
1945 queued_requests: 0,
1946 memory_usage: ferrum_types::MemoryUsage {
1947 total_bytes: 900,
1948 used_bytes: 500,
1949 free_bytes: 400,
1950 gpu_memory_bytes: Some(500),
1951 cpu_memory_bytes: None,
1952 cache_memory_bytes: 100,
1953 utilization_percent: 500.0 / 9.0,
1954 },
1955 uptime_seconds: 0,
1956 last_heartbeat: chrono::Utc::now(),
1957 version: "test".to_string(),
1958 };
1959
1960 let observation = ActualMemoryStageObservation::new("test", "cache_allocated", None, None)
1961 .with_engine_cache_status(&status);
1962
1963 assert_eq!(observation.attributes["kv_cache_total_bytes"], 500);
1964 assert_eq!(observation.attributes["kv_cache_used_bytes"], 100);
1965 assert_eq!(observation.attributes["resource_total_bytes"], 900);
1966 assert_eq!(observation.attributes["resource_used_bytes"], 500);
1967 }
1968
1969 #[test]
1970 fn synthetic_product_observability_writes_profile_paths() {
1971 let root = std::env::temp_dir().join(format!(
1972 "ferrum-product-observability-{}",
1973 Uuid::new_v4().simple()
1974 ));
1975 let config = ProductObservabilityConfig::new(
1976 ProfileEntrypoint::Run,
1977 SYNTHETIC_MODEL,
1978 Some(&root.join("profile.jsonl")),
1979 ProfileDetailArg::Basic,
1980 Some(&root.join("memory.jsonl")),
1981 Some(&root.join("scheduler.jsonl")),
1982 Some(&root.join("request_dump")),
1983 1.0,
1984 );
1985 let written = write_synthetic_product_observability(&config).unwrap();
1986 assert!(written.len() >= 14);
1987 assert!(root.join("profile.jsonl").is_file());
1988 assert!(root.join("memory.jsonl").is_file());
1989 assert!(root.join("scheduler.jsonl").is_file());
1990 assert!(root.join("request_dump/request.json").is_file());
1991 assert!(root.join("request_dump/replay_command.txt").is_file());
1992 let request_dump_root = root.join("request_dump");
1993 let bundle_dir = fs::read_dir(&request_dump_root)
1994 .unwrap()
1995 .flatten()
1996 .find_map(|entry| entry.path().is_dir().then_some(entry.path()))
1997 .expect("request-id replay bundle directory should exist");
1998 assert!(bundle_dir.join("prompt_token_ids.json").is_file());
1999 assert!(bundle_dir.join("sampling_params.json").is_file());
2000 assert!(bundle_dir.join("runtime_effective_config.json").is_file());
2001 assert!(bundle_dir.join("backend_selection.json").is_file());
2002 assert!(bundle_dir.join("output_token_ids.json").is_file());
2003 assert!(bundle_dir.join("output_text.txt").is_file());
2004 assert!(bundle_dir.join("bad_output_scan.json").is_file());
2005 assert!(bundle_dir.join("replay.command.json").is_file());
2006 let replay: serde_json::Value = serde_json::from_str(
2007 &fs::read_to_string(bundle_dir.join("replay.command.json")).unwrap(),
2008 )
2009 .unwrap();
2010 let engine_argv = replay["engine_replay"]["argv"].as_array().unwrap();
2011 assert!(engine_argv.iter().any(|item| item == "replay-bundle"));
2012 assert_eq!(replay["engine_replay"]["requires_http_server"], false);
2013 fs::remove_dir_all(root).ok();
2014 }
2015
2016 #[test]
2017 fn aliased_profile_roles_write_each_event_once() {
2018 let root = std::env::temp_dir().join(format!(
2019 "ferrum-product-observability-alias-{}",
2020 Uuid::new_v4().simple()
2021 ));
2022 let combined = root.join("combined.jsonl");
2023 let memory_alias = root.join(".").join("combined.jsonl");
2024 let scheduler_alias = root.join("not-created").join("..").join("combined.jsonl");
2025 let config = ProductObservabilityConfig::new(
2026 ProfileEntrypoint::Run,
2027 SYNTHETIC_MODEL,
2028 Some(&combined),
2029 ProfileDetailArg::Resource,
2030 Some(&memory_alias),
2031 Some(&scheduler_alias),
2032 None,
2033 1.0,
2034 );
2035
2036 let written = write_synthetic_product_observability(&config).unwrap();
2037 assert_eq!(written.len(), 1);
2038 let events = fs::read_to_string(&combined)
2039 .unwrap()
2040 .lines()
2041 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2042 .collect::<Vec<_>>();
2043 assert_eq!(
2044 events.len(),
2045 6,
2046 "aliased roles duplicated events: {events:#?}"
2047 );
2048 assert_eq!(
2049 events
2050 .iter()
2051 .filter_map(|event| event["event_id"].as_str())
2052 .collect::<std::collections::BTreeSet<_>>()
2053 .len(),
2054 6
2055 );
2056 fs::remove_dir_all(root).ok();
2057 }
2058
2059 #[test]
2060 fn actual_serve_memory_stage_observability_appends_shutdown() {
2061 let root = std::env::temp_dir().join(format!(
2062 "ferrum-serve-memory-observability-{}",
2063 Uuid::new_v4().simple()
2064 ));
2065 let config = ProductObservabilityConfig::new(
2066 ProfileEntrypoint::Serve,
2067 "Qwen/Qwen3-0.6B",
2068 Some(&root.join("profile.jsonl")),
2069 ProfileDetailArg::Basic,
2070 Some(&root.join("memory.jsonl")),
2071 Some(&root.join("scheduler.jsonl")),
2072 Some(&root.join("request_dump")),
2073 1.0,
2074 );
2075 let memory = crate::memory_profile::ProcessMemoryObservation {
2076 before_bytes: 100,
2077 after_bytes: 200,
2078 current_bytes: 200,
2079 high_water_bytes: 240,
2080 source: "test",
2081 };
2082 write_actual_serve_startup_observability(
2083 &config,
2084 42,
2085 Some(memory.clone()),
2086 vec![
2087 ActualMemoryStageObservation::new(
2088 "actual_serve_process_start",
2089 "process_start",
2090 None,
2091 Some(memory.clone()),
2092 ),
2093 ActualMemoryStageObservation::new(
2094 "actual_serve_backend_initialized",
2095 "backend_initialized",
2096 None,
2097 Some(memory.clone()),
2098 ),
2099 ],
2100 )
2101 .unwrap();
2102 append_actual_serve_memory_stage_observability(
2103 &config,
2104 ActualMemoryStageObservation::new(
2105 "actual_serve_shutdown",
2106 "shutdown",
2107 None,
2108 Some(memory),
2109 ),
2110 )
2111 .unwrap();
2112 let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2113 assert!(profile.contains("\"phase\":\"actual_serve_startup\""));
2114 assert!(profile.contains("\"phase\":\"actual_serve_shutdown\""));
2115 let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2116 let memory_stages = memory_profile
2117 .lines()
2118 .filter(|line| !line.trim().is_empty())
2119 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2120 .filter_map(|event| {
2121 event["attributes"]["memory_stage"]
2122 .as_str()
2123 .map(str::to_string)
2124 })
2125 .collect::<Vec<_>>();
2126 assert!(memory_stages.contains(&"process_start".to_string()));
2127 assert!(memory_stages.contains(&"backend_initialized".to_string()));
2128 assert!(memory_stages.contains(&"model_loaded".to_string()));
2129 assert!(memory_stages.contains(&"shutdown".to_string()));
2130 fs::remove_dir_all(root).ok();
2131 }
2132
2133 #[test]
2134 fn profile_jsonl_append_is_parseable_under_concurrent_writers() {
2135 let root = std::env::temp_dir().join(format!(
2136 "ferrum-profile-concurrent-append-{}",
2137 Uuid::new_v4().simple()
2138 ));
2139 let path = root.join("profile.jsonl");
2140 let config = ProductObservabilityConfig::new(
2141 ProfileEntrypoint::Serve,
2142 "Qwen/Qwen3-0.6B",
2143 Some(&path),
2144 ProfileDetailArg::Basic,
2145 None,
2146 None,
2147 Some(&root.join("request_dump")),
2148 1.0,
2149 );
2150
2151 let mut handles = Vec::new();
2152 for writer in 0..8 {
2153 let path = path.clone();
2154 let config = config.clone();
2155 handles.push(std::thread::spawn(move || {
2156 for seq in 0..32 {
2157 let request_id = format!("req-{writer}-{seq}");
2158 let mut event = actual_base_event(
2159 &config,
2160 &request_id,
2161 "chat_completions_sync_complete",
2162 ProfileEventKind::TimedSpan,
2163 Utc::now(),
2164 );
2165 event.event_id = format!("evt-{writer}-{seq}");
2166 event.correlation_id = Some(format!("corr-{writer}-{seq}"));
2167 event.duration_us = Some(1);
2168 event.attributes.insert("writer".to_string(), json!(writer));
2169 event.attributes.insert("seq".to_string(), json!(seq));
2170 append_profile_jsonl(&path, &[event]).unwrap();
2171 }
2172 }));
2173 }
2174
2175 for handle in handles {
2176 handle.join().unwrap();
2177 }
2178
2179 let profile = fs::read_to_string(&path).unwrap();
2180 let mut parsed = 0usize;
2181 for line in profile.lines().filter(|line| !line.trim().is_empty()) {
2182 serde_json::from_str::<serde_json::Value>(line).unwrap();
2183 parsed += 1;
2184 }
2185 assert_eq!(parsed, 8 * 32);
2186 fs::remove_dir_all(root).ok();
2187 }
2188
2189 #[test]
2190 fn actual_serve_startup_memory_orders_model_profile_and_cache_stages() {
2191 let root = std::env::temp_dir().join(format!(
2192 "ferrum-serve-memory-order-{}",
2193 Uuid::new_v4().simple()
2194 ));
2195 let config = ProductObservabilityConfig::new(
2196 ProfileEntrypoint::Serve,
2197 "Qwen/Qwen3-0.6B",
2198 Some(&root.join("profile.jsonl")),
2199 ProfileDetailArg::Basic,
2200 Some(&root.join("memory.jsonl")),
2201 Some(&root.join("scheduler.jsonl")),
2202 Some(&root.join("request_dump")),
2203 1.0,
2204 );
2205 let memory = crate::memory_profile::ProcessMemoryObservation {
2206 before_bytes: 100,
2207 after_bytes: 200,
2208 current_bytes: 200,
2209 high_water_bytes: 240,
2210 source: "test",
2211 };
2212 write_actual_serve_startup_observability(
2213 &config,
2214 42,
2215 Some(memory.clone()),
2216 vec![
2217 ActualMemoryStageObservation::new(
2218 "actual_serve_process_start",
2219 "process_start",
2220 None,
2221 Some(memory.clone()),
2222 ),
2223 ActualMemoryStageObservation::new(
2224 "actual_serve_backend_initialized",
2225 "backend_initialized",
2226 None,
2227 Some(memory.clone()),
2228 ),
2229 ActualMemoryStageObservation::new(
2230 "actual_serve_profile_run_done",
2231 "profile_run_done",
2232 None,
2233 Some(memory.clone()),
2234 )
2235 .with_profile_run_status(false, "not_configured", "test"),
2236 ActualMemoryStageObservation::new(
2237 "actual_serve_cache_allocated",
2238 "cache_allocated",
2239 None,
2240 Some(memory),
2241 )
2242 .with_attribute("available_kv_or_state_bytes", json!(0)),
2243 ],
2244 )
2245 .unwrap();
2246 let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2247 let memory_stages = memory_profile
2248 .lines()
2249 .filter(|line| !line.trim().is_empty())
2250 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2251 .filter_map(|event| {
2252 event["attributes"]["memory_stage"]
2253 .as_str()
2254 .map(str::to_string)
2255 })
2256 .collect::<Vec<_>>();
2257 assert_eq!(
2258 memory_stages,
2259 vec![
2260 "process_start",
2261 "backend_initialized",
2262 "model_loaded",
2263 "profile_run_done",
2264 "cache_allocated"
2265 ]
2266 );
2267 fs::remove_dir_all(root).ok();
2268 }
2269
2270 #[test]
2271 fn actual_run_failure_observability_writes_diagnostics_bundle() {
2272 let root = std::env::temp_dir().join(format!(
2273 "ferrum-run-failure-observability-{}",
2274 Uuid::new_v4().simple()
2275 ));
2276 let config = ProductObservabilityConfig::new(
2277 ProfileEntrypoint::Run,
2278 "Qwen/Qwen3-0.6B",
2279 Some(&root.join("profile.jsonl")),
2280 ProfileDetailArg::Basic,
2281 Some(&root.join("memory.jsonl")),
2282 Some(&root.join("scheduler.jsonl")),
2283 Some(&root.join("request_dump")),
2284 1.0,
2285 );
2286 let request_id = "req-failure-test".to_string();
2287 write_actual_run_failure_observability(
2288 &config,
2289 &ActualRunFailureObservation {
2290 request_id: request_id.clone(),
2291 duration_us: 42,
2292 sampling_params: SamplingParams::greedy(),
2293 prompt_token_ids: Some(vec![11, 22, 33]),
2294 prompt_token_count: Some(3),
2295 prompt_chars: 12,
2296 failure_kind: "error".to_string(),
2297 error_kind: "error".to_string(),
2298 error_message: "synthetic failure".to_string(),
2299 memory: None,
2300 memory_stages: Vec::new(),
2301 },
2302 )
2303 .unwrap();
2304 let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2305 let failure = profile
2306 .lines()
2307 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2308 .find(|event| event["phase"] == "actual_run_generation_failed")
2309 .expect("run failure profile event");
2310 assert_eq!(failure["event_kind"], "timed_span");
2311 assert_eq!(failure["status"], "failure");
2312 assert_eq!(failure["duration_us"], 42);
2313 assert_eq!(failure["attributes"]["terminal_failure_event"], true);
2314 assert!(failure["attributes"]["first_failure_event"].is_null());
2315 let bundle_dir = root.join("request_dump").join(&request_id);
2316 assert!(bundle_dir.join("failure_diagnostics.json").is_file());
2317 let scan: serde_json::Value = serde_json::from_str(
2318 &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2319 )
2320 .unwrap();
2321 assert_eq!(scan["failure_kind"], "error");
2322 let diagnostics: serde_json::Value = serde_json::from_str(
2323 &fs::read_to_string(bundle_dir.join("failure_diagnostics.json")).unwrap(),
2324 )
2325 .unwrap();
2326 assert_eq!(diagnostics["failure_kind"], "error");
2327 assert_eq!(
2328 diagnostics["first_failure_event"]["phase"],
2329 "actual_run_generation_failed"
2330 );
2331 fs::remove_dir_all(root).ok();
2332 }
2333
2334 #[test]
2335 fn actual_run_observability_writes_prompt_token_ids() {
2336 let root = std::env::temp_dir().join(format!(
2337 "ferrum-run-observability-{}",
2338 Uuid::new_v4().simple()
2339 ));
2340 let config = ProductObservabilityConfig::new(
2341 ProfileEntrypoint::Run,
2342 "Qwen/Qwen3-0.6B",
2343 Some(&root.join("profile.jsonl")),
2344 ProfileDetailArg::Latency,
2345 Some(&root.join("memory.jsonl")),
2346 Some(&root.join("scheduler.jsonl")),
2347 Some(&root.join("request_dump")),
2348 1.0,
2349 );
2350 let request_id = "req-run-test".to_string();
2351 let native_event = actual_base_event(
2352 &config,
2353 &request_id,
2354 "vnext.request_accepted",
2355 ProfileEventKind::Instant,
2356 Utc::now(),
2357 );
2358 write_profile_jsonl(&root.join("profile.jsonl"), &[native_event]).unwrap();
2359 write_actual_run_observability(
2360 &config,
2361 &ActualRunObservation {
2362 request_id: request_id.clone(),
2363 duration_us: 42,
2364 sampling_params: SamplingParams::greedy(),
2365 prompt_token_ids: Some(vec![7, 8, 9]),
2366 prompt_token_count: Some(3),
2367 output_tokens: 2,
2368 output_token_ids: vec![10, 11],
2369 chunk_count: 1,
2370 finish_reason: Some("stop".to_string()),
2371 prompt_chars: 12,
2372 response_chars: 2,
2373 response_text: "OK".to_string(),
2374 execution_evidence: Some(ferrum_types::InferenceExecutionEvidence {
2375 prompt_token_ids: vec![
2376 ferrum_types::TokenId::new(7),
2377 ferrum_types::TokenId::new(8),
2378 ferrum_types::TokenId::new(9),
2379 ],
2380 output_token_ids: vec![
2381 ferrum_types::TokenId::new(10),
2382 ferrum_types::TokenId::new(11),
2383 ],
2384 engine_token_timing: Some(ferrum_types::EngineTokenTimingEvidence {
2385 clock_source: "rust_std_instant".to_string(),
2386 wall_anchor_unix_nanos: 1_700_000_000_000_000_000,
2387 wall_anchor_max_error_nanos: 500,
2388 decode_ready_nanos_since_request_start: Some(1_000_000),
2389 token_commit_nanos_since_request_start: vec![2_000_000, 4_000_000],
2390 decode_stage_intervals: Vec::new(),
2391 }),
2392 }),
2393 memory: None,
2394 memory_stages: vec![
2395 ActualMemoryStageObservation::new(
2396 "actual_run_process_start",
2397 "process_start",
2398 None,
2399 Some(crate::memory_profile::ProcessMemoryObservation {
2400 before_bytes: 100,
2401 after_bytes: 100,
2402 current_bytes: 100,
2403 high_water_bytes: 120,
2404 source: "test",
2405 }),
2406 ),
2407 ActualMemoryStageObservation::new(
2408 "actual_run_shutdown",
2409 "shutdown",
2410 None,
2411 Some(crate::memory_profile::ProcessMemoryObservation {
2412 before_bytes: 200,
2413 after_bytes: 220,
2414 current_bytes: 220,
2415 high_water_bytes: 240,
2416 source: "test",
2417 }),
2418 ),
2419 ],
2420 },
2421 )
2422 .unwrap();
2423 let bundle_dir = root.join("request_dump").join(&request_id);
2424 let prompt_tokens: serde_json::Value = serde_json::from_str(
2425 &fs::read_to_string(bundle_dir.join("prompt_token_ids.json")).unwrap(),
2426 )
2427 .unwrap();
2428 assert_eq!(prompt_tokens["token_ids"], serde_json::json!([7, 8, 9]));
2429 assert_eq!(prompt_tokens["token_count"], 3);
2430 assert!(prompt_tokens["unavailable_reason"].is_null());
2431 let output_text_bytes = fs::read(bundle_dir.join("output_text.txt")).unwrap();
2432 let output_text = String::from_utf8(output_text_bytes.clone()).unwrap();
2433 assert!(output_text.starts_with("[redacted actual output]\n"));
2434 let scan: serde_json::Value = serde_json::from_str(
2435 &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2436 )
2437 .unwrap();
2438 assert_eq!(
2439 scan["output_sha256"],
2440 sha256_hex(output_text_bytes.as_slice())
2441 );
2442 assert_eq!(scan["classified_output_sha256"], sha256_hex(b"OK"));
2443 let profile = fs::read_to_string(root.join("profile.jsonl")).unwrap();
2444 assert!(profile.lines().any(|line| {
2445 serde_json::from_str::<serde_json::Value>(line)
2446 .is_ok_and(|event| event["phase"] == "vnext.request_accepted")
2447 }));
2448 let generation = profile
2449 .lines()
2450 .filter(|line| !line.trim().is_empty())
2451 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2452 .find(|event| event["phase"] == "actual_run_generation")
2453 .expect("actual run generation event");
2454 assert_eq!(generation["attributes"]["prompt_token_count"], 3);
2455 assert_eq!(generation["attributes"]["completion_token_count"], 2);
2456 assert_eq!(generation["attributes"]["output_token_count"], 2);
2457 assert_eq!(generation["attributes"]["total_token_count"], 5);
2458 assert_eq!(
2459 generation["attributes"]["token_count_source"],
2460 "rendered_prompt_and_generated_tokens"
2461 );
2462 assert_eq!(generation["attributes"]["e2e_duration_us"], 42);
2463 assert_eq!(generation["attributes"]["profile_detail"], "latency");
2464 assert_eq!(
2465 generation["attributes"]["engine_token_commit_nanos_since_request_start"],
2466 serde_json::json!([2_000_000, 4_000_000])
2467 );
2468 assert_eq!(generation["attributes"]["engine_token_commit_count"], 2);
2469 assert_eq!(
2470 generation["attributes"]["itl_source"],
2471 "engine_token_commit"
2472 );
2473 assert_eq!(
2474 generation["attributes"]["itl_nanos"],
2475 serde_json::json!([2_000_000])
2476 );
2477 assert_eq!(generation["attributes"]["ttft_us"], 2_000);
2478 assert_eq!(generation["attributes"]["itl_us_avg"], 2_000);
2479 assert_eq!(
2480 generation["attributes"]["engine_decode_ready_nanos_since_request_start"],
2481 1_000_000
2482 );
2483 assert_eq!(
2484 generation["attributes"]["engine_decode_wall_nanos"],
2485 3_000_000
2486 );
2487 assert_eq!(generation["attributes"]["clock_conversion_error_ppm"], 166);
2488 assert_eq!(
2489 generation["attributes"]["decode_wall_timing_eligible"],
2490 true
2491 );
2492 let memory_profile = fs::read_to_string(root.join("memory.jsonl")).unwrap();
2493 let memory_stages = memory_profile
2494 .lines()
2495 .filter(|line| !line.trim().is_empty())
2496 .map(|line| serde_json::from_str::<serde_json::Value>(line).unwrap())
2497 .filter_map(|event| {
2498 event["attributes"]["memory_stage"]
2499 .as_str()
2500 .map(str::to_string)
2501 })
2502 .collect::<Vec<_>>();
2503 assert!(memory_stages.contains(&"process_start".to_string()));
2504 assert!(memory_stages.contains(&"first_request_done".to_string()));
2505 let first_request_index = memory_stages
2506 .iter()
2507 .position(|stage| stage == "first_request_done")
2508 .expect("first_request_done stage");
2509 let shutdown_index = memory_stages
2510 .iter()
2511 .position(|stage| stage == "shutdown")
2512 .expect("shutdown stage");
2513 assert!(first_request_index < shutdown_index);
2514 assert!(
2515 !root.join("scheduler.jsonl").exists(),
2516 "the engine owns successful actual-run scheduler lifecycles"
2517 );
2518 fs::remove_dir_all(root).ok();
2519 }
2520
2521 #[test]
2522 fn actual_run_resource_failure_observability_writes_resource_diagnostics() {
2523 let root = std::env::temp_dir().join(format!(
2524 "ferrum-observability-resource-failure-{}",
2525 uuid::Uuid::new_v4()
2526 ));
2527 fs::create_dir_all(&root).unwrap();
2528 let config = ProductObservabilityConfig::new(
2529 ProfileEntrypoint::Run,
2530 "Qwen/Qwen3-0.6B",
2531 Some(&root.join("profile.jsonl")),
2532 ProfileDetailArg::Basic,
2533 Some(&root.join("memory.jsonl")),
2534 Some(&root.join("scheduler.jsonl")),
2535 Some(&root.join("request_dump")),
2536 1.0,
2537 );
2538 let request_id = "req-resource-failure-test".to_string();
2539 write_actual_run_failure_observability(
2540 &config,
2541 &ActualRunFailureObservation {
2542 request_id: request_id.clone(),
2543 duration_us: 42,
2544 sampling_params: SamplingParams::greedy(),
2545 prompt_token_ids: Some(vec![1, 2, 3, 4]),
2546 prompt_token_count: Some(4),
2547 prompt_chars: 128,
2548 failure_kind: "oom_admission".to_string(),
2549 error_kind: "resource_exhausted".to_string(),
2550 error_message: "Resource exhausted: recurrent state capacity exhausted".to_string(),
2551 memory: Some(crate::memory_profile::ProcessMemoryObservation {
2552 before_bytes: 1024,
2553 after_bytes: 2048,
2554 current_bytes: 2048,
2555 high_water_bytes: 4096,
2556 source: "test",
2557 }),
2558 memory_stages: Vec::new(),
2559 },
2560 )
2561 .unwrap();
2562 let bundle_dir = root.join("request_dump").join(&request_id);
2563 let scan: serde_json::Value = serde_json::from_str(
2564 &fs::read_to_string(bundle_dir.join("bad_output_scan.json")).unwrap(),
2565 )
2566 .unwrap();
2567 assert_eq!(scan["failure_kind"], "oom_admission");
2568 let diagnostics: serde_json::Value = serde_json::from_str(
2569 &fs::read_to_string(bundle_dir.join("failure_diagnostics.json")).unwrap(),
2570 )
2571 .unwrap();
2572 assert_eq!(diagnostics["failure_kind"], "oom_admission");
2573 assert_eq!(
2574 diagnostics["capacity"]["resource_kind"],
2575 "admission_capacity"
2576 );
2577 assert_eq!(diagnostics["nearest_resource_event"]["action"], "reject");
2578 assert_eq!(
2579 diagnostics["nearest_memory_snapshot"]["current_bytes"],
2580 2048
2581 );
2582 fs::remove_dir_all(root).ok();
2583 }
2584}