增加UI自动切分耗时日志

补充 marker、area、LLM、图片编辑及 batch 阶段耗时观测
记录成功与失败路径的性能字段
同步自动切分工作流技术方案中的日志约定

apps/ai-game-creator-shell/src-tauri/src/ui_editor/commands/separation/area.rs

@@ -1,5 +1,6 @@
 use super::model::BindingArea;
 use image::RgbaImage;
+use std::time::Instant;
 
 /// Each edge may move by at most this percentage of the corresponding area
 /// dimension returned by the visual model. Keep this policy explicit so
@@ -215,16 +216,31 @@ pub(crate) fn normalize_binding_area(
     image: &RgbaImage,
     original_area: BindingArea,
 ) -> Result<NormalizedBindingArea, String> {
-    original_area.validate_in(image.width(), image.height())?;
+    let started = Instant::now();
+    if let Err(error) = original_area.validate_in(image.width(), image.height()) {
+        app_log!(
+            "ui_separation.area.timing outcome=error elapsed_us={} rounds=0 image_width={} image_height={} area=({}, {}, {}, {})",
+            started.elapsed().as_micros(),
+            image.width(),
+            image.height(),
+            original_area.global_pos_x_px,
+            original_area.global_pos_y_px,
+            original_area.width_px,
+            original_area.height_px
+        );
+        return Err(error);
+    }
     let original = Rect::from_area(original_area);
     let directions = Edge::ALL.map(|edge| edge_direction(image, original, edge));
     let mut current = original;
     let mut clamped = false;
     let mut active = [true; 4];
+    let mut rounds = 0u32;
 
     // TODO: Replace the deliberately simple pixel-by-pixel scan if real UI
     // design sizes show this path to be a measurable bottleneck.
     while active.iter().any(|value| *value) {
+        rounds = rounds.saturating_add(1);
         let before = current;
         let mut next = current;
         let mut moved = [false; 4];
@@ -277,12 +293,27 @@ pub(crate) fn normalize_binding_area(
     }
 
     let area = current.into_area();
-    Ok(NormalizedBindingArea {
+    let result = Ok(NormalizedBindingArea {
         changed: area != original_area,
         area,
         clamped,
         transparent: !rect_has_visible_pixel(image, current),
-    })
+    });
+    app_log!(
+        "ui_separation.area.timing outcome=ok elapsed_us={} rounds={} image_width={} image_height={} area=({}, {}, {}, {}) changed={} clamped={} transparent={}",
+        started.elapsed().as_micros(),
+        rounds,
+        image.width(),
+        image.height(),
+        original_area.global_pos_x_px,
+        original_area.global_pos_y_px,
+        original_area.width_px,
+        original_area.height_px,
+        result.as_ref().expect("normalization result exists").changed,
+        result.as_ref().expect("normalization result exists").clamped,
+        result.as_ref().expect("normalization result exists").transparent
+    );
+    result
 }
 
 #[cfg(test)]

apps/ai-game-creator-shell/src-tauri/src/ui_editor/commands/separation/marker.rs

@@ -2,6 +2,7 @@ use super::model::SeparationNode;
 use base64::Engine as _;
 use std::path::Path;
 use std::path::PathBuf;
+use std::time::Instant;
 
 const MARKER_LINE_WIDTH: u32 = 2;
 const PURPLE_FILL: image::Rgba<u8> = image::Rgba([180, 0, 180, 120]);
@@ -11,9 +12,31 @@ pub async fn build_marked_image(
     nodes: Vec<SeparationNode>,
     target: PathBuf,
 ) -> Result<String, String> {
-    tokio::task::spawn_blocking(move || build_marked_image_blocking(&source_url, &nodes, &target))
-        .await
-        .map_err(|error| format!("构建标记图任务失败：{error}"))?
+    let node_count = nodes.len();
+    let started = Instant::now();
+    let result = match tokio::task::spawn_blocking(move || {
+        let blocking_started = Instant::now();
+        let result = build_marked_image_blocking(&source_url, &nodes, &target);
+        app_log!(
+            "ui_separation.marker.blocking_timing outcome={} elapsed_ms={} nodes={}",
+            if result.is_ok() { "ok" } else { "error" },
+            blocking_started.elapsed().as_millis(),
+            node_count
+        );
+        result
+    })
+    .await
+    {
+        Ok(result) => result,
+        Err(error) => Err(format!("构建标记图任务失败：{error}")),
+    };
+    app_log!(
+        "ui_separation.marker.timing outcome={} elapsed_ms={} nodes={}",
+        if result.is_ok() { "ok" } else { "error" },
+        started.elapsed().as_millis(),
+        node_count
+    );
+    result
 }
 
 fn build_marked_image_blocking(

apps/ai-game-creator-shell/src-tauri/src/ui_editor/commands/separation/workflow.rs

@@ -18,6 +18,7 @@ use platform_llm::{
 use serde::Deserialize;
 use std::fs;
 use std::path::{Path, PathBuf};
+use std::time::Instant;
 pub fn apply_batch_patch(
     state: &mut SeparationState,
     tree_index: usize,
@@ -65,7 +66,7 @@ pub fn apply_batch_patch(
             }
             BindingDecision::NeedRework {
                 to_node,
-                problem_description,
+                advice: problem_description,
             } => {
                 append_rework_note(&mut tree.root, to_node, problem_description);
                 let count = rework_counts.get(to_node).copied().unwrap_or(0) + 1;
@@ -125,6 +126,25 @@ async fn raw_image_edit(
     prompt: &str,
     width: u32,
     height: u32,
+) -> Result<String, String> {
+    let started = Instant::now();
+    let result = raw_image_edit_inner(session, image_data_url, prompt, width, height).await;
+    app_log!(
+        "ui_separation.image_edit.timing outcome={} elapsed_ms={} width={} height={}",
+        if result.is_ok() { "ok" } else { "error" },
+        started.elapsed().as_millis(),
+        width,
+        height
+    );
+    result
+}
+
+async fn raw_image_edit_inner(
+    session: &crate::platform_session::PlatformSessionSnapshot,
+    image_data_url: &str,
+    prompt: &str,
+    width: u32,
+    height: u32,
 ) -> Result<String, String> {
     app_log!(
         "ui_separation.image_edit.start width={} height={} prompt_chars={}",
@@ -208,6 +228,17 @@ async fn raw_image_edit(
 }
 
 async fn write_processed_image(processed_url: String, target: PathBuf) -> Result<(), String> {
+    let started = Instant::now();
+    let result = write_processed_image_inner(processed_url, target).await;
+    app_log!(
+        "ui_separation.processed_image.write.timing outcome={} elapsed_ms={}",
+        if result.is_ok() { "ok" } else { "error" },
+        started.elapsed().as_millis()
+    );
+    result
+}
+
+async fn write_processed_image_inner(processed_url: String, target: PathBuf) -> Result<(), String> {
     app_log!(
         "ui_separation.processed_image.write.start target_file={} data_url_chars={}",
         target
@@ -247,6 +278,22 @@ async fn visual_binding(
     source_url: String,
     processed_url: String,
     nodes: &[&SeparationNode],
+) -> Result<BindingResp, String> {
+    let started = Instant::now();
+    let result = visual_binding_inner(source_url, processed_url, nodes).await;
+    app_log!(
+        "ui_separation.visual_binding.timing outcome={} elapsed_ms={} nodes={}",
+        if result.is_ok() { "ok" } else { "error" },
+        started.elapsed().as_millis(),
+        nodes.len()
+    );
+    result
+}
+
+async fn visual_binding_inner(
+    source_url: String,
+    processed_url: String,
+    nodes: &[&SeparationNode],
 ) -> Result<BindingResp, String> {
     app_log!(
         "ui_separation.visual_binding.start nodes={} source_url_chars={} processed_url_chars={}",
@@ -304,8 +351,14 @@ async fn visual_binding(
                 let request = LlmRunRequest::new(history)
                     .with_function_tools(vec![tool.clone()])
                     .with_tool_choice(LlmToolChoice::Required);
-                request_ui_editor_llm(&client, &llm_config, request)
-                    .await
+                let request_started = Instant::now();
+                let response = request_ui_editor_llm(&client, &llm_config, request).await;
+                app_log!(
+                    "ui_separation.llm.timing outcome={} elapsed_ms={}",
+                    if response.is_ok() { "ok" } else { "error" },
+                    request_started.elapsed().as_millis()
+                );
+                response
                     .map_err(|e| e.to_string())
                     .and_then(|response| {
                         response
@@ -425,6 +478,7 @@ pub(crate) async fn separate_ui_impl(
         })?;
         let mut batch_index = 0usize;
         loop {
+            let batch_started = Instant::now();
             let Some(current_tree) = separation.trees.get(tree_index) else {
                 break;
             };
@@ -568,12 +622,13 @@ pub(crate) async fn separate_ui_impl(
             apply_batch_patch(&mut separation, tree_index, &binding.decisions, &cut_paths)?;
             write_separation_state(&state_path, &separation)?;
             app_log!(
-                "ui_separation.batch_completed tree_index={} batch_index={} cuts={} bound={} problematic={}",
+                "ui_separation.batch_completed tree_index={} batch_index={} cuts={} bound={} problematic={} elapsed_ms={}",
                 tree_index,
                 batch_index,
                 cut_paths.len(),
                 separation.bound.len(),
-                separation.problematic_nodes.len()
+                separation.problematic_nodes.len(),
+                batch_started.elapsed().as_millis()
             );
             batch_index += 1;
         }
@@ -591,6 +646,21 @@ async fn cut_processed_image(
     source: PathBuf,
     area: BindingArea,
     target: PathBuf,
+) -> Result<(), String> {
+    let started = Instant::now();
+    let result = cut_processed_image_inner(source, area, target).await;
+    app_log!(
+        "ui_separation.cut_image.timing outcome={} elapsed_ms={}",
+        if result.is_ok() { "ok" } else { "error" },
+        started.elapsed().as_millis()
+    );
+    result
+}
+
+async fn cut_processed_image_inner(
+    source: PathBuf,
+    area: BindingArea,
+    target: PathBuf,
 ) -> Result<(), String> {
     app_log!(
         "ui_separation.cut_image.start source_file={} target_file={} area=({}, {}, {}, {})",

docs/technical/【技术方案】UI编辑器自动切分素材工作流-2026-09-08.md

@@ -56,6 +56,7 @@ Rust 在接收并校验工具结果后，才把这两个枚举变体映射为正
 - 达到返工上限时仍先保留最后一条视觉模型意见，再把节点追加到 problematic；网络、IO、裁切等基础设施错误不写入节点意见。
 - 达到模块级重做常量后，节点移入 problematic；不中断整条工作流，最终统一通知用户。image-edit、图像写入或裁切失败保留当前 state 并返回错误，不自动把整批标记为 problematic。
 - 父节点背景重建由 image-edit 模型完成，不由 Rust 硬编码重建算法完成。
+- 性能观测沿用 `app_log!`：marker 记录端到端与 `spawn_blocking` 耗时，area 记录 `elapsed_us` 与扫描轮数，image-edit 与 visual binding 记录整个请求耗时，处理图写入、cut 和 batch 记录阶段耗时；日志不写入 prompt、图片内容、绝对路径或模型原文。
 
 ## 临时 sidecar