Profile and preinitialize viewport rendering

crates/metacrate-grid-agent/tests/live_renderer.rs

@@ -50,6 +50,56 @@ async fn live_primary_login_resolves_varregion_dimensions() -> Result<(), Box<dy
     result
 }
 
+#[tokio::test(flavor = "multi_thread", worker_threads = 4)]
+#[ignore = "profiles primary login, renderer initialization, and first visible-scene warmup"]
+async fn live_primary_startup_profile() -> Result<(), Box<dyn Error>> {
+    let total_started = Instant::now();
+    let environment = live_environment()?;
+    let owner_started = Instant::now();
+    let owner = LibremetaverseClientOwner::new()?;
+    let owner_initialization = owner_started.elapsed();
+    let gpu_task = tokio::task::spawn_blocking(|| {
+        let started = Instant::now();
+        (
+            metacrate_rendering_wgpu::Renderer::new_blocking(),
+            started.elapsed(),
+        )
+    });
+    let login_started = Instant::now();
+    let (mut session, cancellation) =
+        login(&owner, &environment, "GRID_USER", "GRID_PASSWORD").await?;
+    let login = login_started.elapsed();
+    let ready_started = Instant::now();
+    wait_ready("primary", &mut session, &cancellation).await?;
+    let readiness = ready_started.elapsed();
+    let settle_started = Instant::now();
+    wait_scene_settled(&owner).await?;
+    let scene_settle = settle_started.elapsed();
+    let limits = VisionLimits {
+        minimum_interval: Duration::ZERO,
+        ..VisionLimits::default()
+    };
+    let source = LibremetaverseSceneSource::new(&owner, limits);
+    let warmup_started = Instant::now();
+    let scene = source.capture_scene(0, cancellation.token()).await?;
+    let scene_warmup = warmup_started.elapsed();
+    let (renderer, gpu_initialization) = gpu_task.await?;
+    renderer?;
+    println!(
+        "LIVE_STARTUP_PROFILE=owner_initialization_ms:{},grid_login_ms:{},grid_readiness_ms:{},scene_settle_ms:{},gpu_initialization_parallel_ms:{},first_scene_warmup_ms:{},first_scene:{:?},total_ms:{}",
+        owner_initialization.as_millis(),
+        login.as_millis(),
+        readiness.as_millis(),
+        scene_settle.as_millis(),
+        gpu_initialization.as_millis(),
+        scene_warmup.as_millis(),
+        scene.timings,
+        total_started.elapsed().as_millis(),
+    );
+    let _ = session.logout(cancellation.token()).await;
+    Ok(())
+}
+
 #[tokio::test(flavor = "multi_thread", worker_threads = 4)]
 #[ignore = "records the primary region's asynchronous map-name reply"]
 async fn live_primary_map_name_reports_varregion_dimensions() -> Result<(), Box<dyn Error>> {
@@ -175,6 +225,14 @@ async fn live_bevy_capture_renders_in_front_of_avatar() -> Result<(), Box<dyn Er
             limits,
         )?
         .prefer_gpu();
+        let initialization_started = Instant::now();
+        if !vision.initialize_renderer().await {
+            return Err("live wgpu renderer initialization failed".into());
+        }
+        println!(
+            "LIVE_RENDER_INITIALIZATION_MILLISECONDS={}",
+            initialization_started.elapsed().as_millis()
+        );
         vision.set_generation(1);
         let mut capture = None;
         let output = std::env::var_os("METACRATE_LIVE_RENDER_OUTPUT").map_or_else(
@@ -215,6 +273,7 @@ async fn live_bevy_capture_renders_in_front_of_avatar() -> Result<(), Box<dyn Er
             }
         }
         let capture = capture.ok_or("live renderer produced no frame")?;
+        profile_warm_capture(&scene_source, limits, renderer_cancel.token()).await?;
         println!("LIVE_RENDER_OUTPUT={}", output.display());
         println!("LIVE_RENDER_SHA256={}", capture.image_sha256);
         Ok::<(), Box<dyn Error>>(())
@@ -226,6 +285,107 @@ async fn live_bevy_capture_renders_in_front_of_avatar() -> Result<(), Box<dyn Er
     result
 }
 
+async fn profile_warm_capture(
+    source: &LibremetaverseSceneSource,
+    limits: VisionLimits,
+    cancellation: CancellationToken,
+) -> Result<(), Box<dyn Error>> {
+    let total_started = Instant::now();
+    let scene_started = Instant::now();
+    let scene = source.capture_scene(1, cancellation).await?;
+    let scene_total = scene_started.elapsed();
+    let preparation_started = Instant::now();
+    let mut renderables = scene
+        .entities
+        .iter()
+        .flat_map(|entity| {
+            entity
+                .renderables
+                .iter()
+                .cloned()
+                .map(move |renderable| (entity.id.to_string(), renderable))
+        })
+        .collect::<Vec<_>>();
+    renderables.sort_by(|left, right| left.0.cmp(&right.0));
+    let renderables = renderables
+        .into_iter()
+        .map(|(_, renderable)| renderable)
+        .collect::<Vec<_>>();
+    let preparation = preparation_started.elapsed();
+    let renderer_started = Instant::now();
+    let renderer = metacrate_rendering_wgpu::Renderer::new_blocking()?;
+    let renderer_initialization = renderer_started.elapsed();
+    let render_limits = metacrate_rendering_wgpu::RenderLimits {
+        width: limits.width,
+        height: limits.height,
+        max_triangles: limits.max_triangles,
+        max_texture_bytes: limits.max_texture_bytes,
+        max_texture_pixels: limits.max_decode_pixels,
+        far_distance: 512,
+    };
+    let first = renderer.render_profiled(
+        scene.camera,
+        &renderables,
+        &scene.textures,
+        [125, 149, 173, 255],
+        render_limits,
+    )?;
+    let warm_started = Instant::now();
+    let warm = renderer.render_profiled(
+        scene.camera,
+        &renderables,
+        &scene.textures,
+        [125, 149, 173, 255],
+        render_limits,
+    )?;
+    let warm_render_total = warm_started.elapsed();
+    let jpeg_started = Instant::now();
+    let rgb = warm
+        .rgba
+        .chunks_exact(4)
+        .flat_map(|pixel| pixel[..3].iter().copied())
+        .collect::<Vec<_>>();
+    let mut jpeg = Vec::new();
+    jpeg_encoder::Encoder::new(&mut jpeg, 92).encode(
+        &rgb,
+        u16::try_from(limits.width)?,
+        u16::try_from(limits.height)?,
+        jpeg_encoder::ColorType::Rgb,
+    )?;
+    let jpeg_encode = jpeg_started.elapsed();
+    println!(
+        "LIVE_RENDER_PROFILE=scene_total_ms:{},terrain_wait_ms:{},object_snapshot_and_asset_discovery_ms:{},material_fetch_ms:{},asset_fetch_ms:{},decode_and_geometry_ms:{},renderable_collection_and_sort_ms:{},renderer_initialization_ms:{},first_render_total_ms:{},first_render:{:?},warm_render_total_ms:{},warm_render:{:?},jpeg_encode_ms:{},profile_total_ms:{}",
+        scene_total.as_millis(),
+        scene.timings.terrain_wait.as_millis(),
+        scene
+            .timings
+            .object_snapshot_and_asset_discovery
+            .as_millis(),
+        scene.timings.material_fetch.as_millis(),
+        scene.timings.asset_fetch.as_millis(),
+        scene.timings.decode_and_geometry.as_millis(),
+        preparation.as_millis(),
+        renderer_initialization.as_millis(),
+        render_total(&first.timings).as_millis(),
+        first.timings,
+        warm_render_total.as_millis(),
+        warm.timings,
+        jpeg_encode.as_millis(),
+        total_started.elapsed().as_millis(),
+    );
+    Ok(())
+}
+
+fn render_total(timings: &metacrate_rendering_wgpu::RenderTimings) -> Duration {
+    timings.validation
+        + timings.command_copy
+        + timings.clear_previous_frame
+        + timings.texture_cache_sync
+        + timings.mesh_cache_sync
+        + timings.scene_setup
+        + timings.capture
+}
+
 struct DiagnosticSceneSource {
     inner: Arc<LibremetaverseSceneSource>,
     material_override: Option<String>,