# PLC 状态写入延迟排查报告

## 1. 问题现象

### 1.1 现象描述

在固定相机检测拍照流程中，代码执行到 `Management.cs` 第 2553 行：

```csharp
await plc.WriteNodeAsync(addressConfig.Out_FixedCameraPickStatus.Address, (Int16)1);
```

调用后，通过外部工具检测对应 OPC UA 节点值未发生变化，使用抓包工具也未观察到对应的 WriteRequest 数据包及时发出。

### 1.2 影响范围

- 受影响节点：`ns=4;s=DB_Communication|FromPC.FixedCameraPickStatus`
- 受影响流程：`PlcCommandTrigger` → `In_FixedCameracheckExe` → 固定相机检测拍照 → 状态回写
- 每个产品周期涉及 6 个相机的采图与状态回写

---

## 2. 问题排查过程

### 2.1 第一轮：架构层面分析（`async void` + OPC UA Session）

**排查方向**：`PlcCommandTrigger` 声明为 `async void`，被 OPC UA 订阅回调直接调用。怀疑回调线程未释放导致 Session 内部锁阻塞 `WriteNodeAsync`。

**措施**：将 `PlcCommandTrigger` 从 `async void` 改为同步包装 + `async Task`：

```csharp
private void PlcCommandTrigger(...)
{
    _ = PlcCommandTriggerAsync(tuple);
}
```

**结论**：`WriteNodeAsync` 本身极快（1-12ms），返回 `result=True`。不是写入操作慢，而是写入调用被前面的代码延迟了。

---

### 2.2 第二轮：添加分层诊断日志

**排查方向**：在各层添加 `[PLC-TRACE]` 前缀的耗时日志，覆盖：

| 层 | 文件 | 日志内容 |
|----|------|----------|
| 业务层 | `Management.cs` | PLC 触发入队、相机触发开始、光源耗时、GrabImageEx 开始/结束、图像处理耗时、status write 前后 |
| OPC 封装层 | `OPCuaClientPLC.cs` | ReadNodesAsync 慢日志、WriteNodeAsync 开始/结束、轮询周期日志、回调处理慢日志 |
| 采图核心 | `RemoteCommandService.cs` | SetExposureTime/SetGain 累计耗时、Grab 前状态 |
| OPT 相机 SDK | `OptCamera.cs` | SetExposureTime/SetGain SDK 耗时、Grab 各子步骤（clearMs/triggerMs/grabMs/convertMs/freeMs） |

**关键日志数据**（第一轮测试）：

| 相机 | enqueue→写入延迟 | status write 耗时 |
|------|-----------------|-------------------|
| FC-1 | 491ms | 1ms |
| FC-2 | 1598ms | 5ms |
| FC-3 | 1062ms | 2ms |
| FC-4 | 1578ms | 5ms |
| FC-5 | 747ms | 3ms |

**结论**：`WriteNodeAsync` 本身极快（1-12ms），全部返回 `result=True`。阻塞发生在写入之前的代码段。

---

### 2.3 第三轮：OPT 相机层精确定位

**排查方向**：锁定 `GrabImageEx` → `ExecuteGrabImageAsync` 内部耗时分布。

**关键日志**：

```
[PLC-TRACE] GrabImageEx ExecuteGrabImageAsync start
[PLC-TRACE] OptCamera SetExposureTime done, elapsedMs=3        ← SDK 本身 3ms
[PLC-TRACE] OptCamera SetGain done, elapsedMs=10               ← SDK 本身 10ms
[PLC-TRACE] before Grab: setExpMs=3, setGainMs=1175            ← !! 1175ms !!
[PLC-TRACE] OptCamera Grab done, totalMs=296                   ← Grab 本身 296ms
```

| 指标 | FC-2 | FC-3 | FC-4 |
|------|------|------|------|
| SetExposureTime SDK | 3ms | 5ms | 5ms |
| SetGain SDK | 10ms | ≤5ms | — |
| **SetExp→SetGain 间隙** | **1162ms** | **694ms** | **1247ms** |
| Grab 耗时 | 296ms | 222ms | 227ms |
| **Grab 占比** | **20%** | **24%** | **15%** |

**结论**：**70-85% 的时间消耗在 `SetExposureTime` 和 `SetGain` 之间**，而不是在 Grab 本身。两者之间唯一的非平凡代码是 `SendTaskMessage` 调用。

---

### 2.4 第四轮：SendTaskMessage 验证

**排查方向**：注释掉 `SetExposureTime` 和 `SetGain` 成功后的 `SendTaskMessage` 调用。

**对比结果**：

| 指标 | FC-2 注释前 | FC-2 注释后 | 改善 |
|------|-----------|-----------|------|
| setGainMs | **1175ms** | **5ms** | -99.6% |
| 总耗时 | **1473ms** | **239ms** | **-84%** |

**确认**：`SendTaskMessage` 就是瓶颈根因。

---

### 2.5 第五轮：根因深层分析

**排查方向**：检查 `SendTaskMessage` 的实现。

发现项目中存在 **4 份独立的 `SendTaskMessage` 副本**：

| 位置 | 方式 | 影响 |
|------|------|------|
| `Management.cs` | `BeginInvoke`（异步） | 之前已修复 |
| **`RemoteCommandService.cs`** | **`Invoke`（同步阻塞）** | **主犯！** |
| `MainWindowViewModel.cs` | 直接 Publish | UI 线程调用，无影响 |
| `AdvancedProcedureViewModel.cs` | `Invoke` | UI 线程调用，无影响 |

`RemoteCommandService.cs` 的 `SendTaskMessage` 使用了 **`Dispatcher.Invoke`（同步等待 UI 线程）**：

```csharp
private void SendTaskMessage(string msg, MessageLevel level)
{
    App.Current.Dispatcher.Invoke(() =>    // ← 同步阻塞！每次等待 700-1462ms
    {
        _eventAggregator.GetEvent<TaskMessageNotification>().Publish(...);
    });
}
```

**阻塞成因**：

1. `Dispatcher.Invoke` 需要 UI 线程空闲才能执行委托
2. UI 线程忙于 Cognex VisionPro 图像渲染、`ObservableCollection` 数据绑定更新
3. 每个产品周期有 50+ 次 `SendTaskMessage` 调用
4. 累积阻塞 = 700-1462ms/相机

---

## 3. 问题排查结论

### 3.1 根本原因

`RemoteCommandService.cs` 中的 `SendTaskMessage` 方法使用了 `Dispatcher.Invoke`（同步阻塞），在采图流程的高频调用下，每次都需要等待 UI 线程空闲，导致累计阻塞 700-1462ms。

### 3.2 时间分布（修复后）

| 环节 | 耗时 | 占比 |
|------|------|------|
| SetExposureTime (SDK) | 2-5ms | 1% |
| SetGain (SDK) | 2-6ms | 1% |
| Grab (硬件采集) | 225-256ms | 96% |
| status write | 1-3ms | 1% |
| **总计** | **~235ms** | |

Grab 的 ~185ms 硬件采集时间是物理极限，无法进一步优化。

---

## 4. 问题解决方法

### 4.1 全局修复方案

将 `SendTaskMessage` 改为 **无锁队列 + 定时器批量推送**，所有调用方零改动。

**Management.cs**：

```csharp
// 新增字段
private readonly ConcurrentQueue<MessageStruct> _messageQueue = new ConcurrentQueue<MessageStruct>();
private Timer _messageFlushTimer;

// 构造函数中初始化（200ms 批量推送）
_messageFlushTimer = new Timer(_ => FlushMessageQueue(), null, 200, 200);

// 改造后的 SendTaskMessage（~0ms）
private void SendTaskMessage(string msg, MessageLevel level)
{
    _messageQueue.Enqueue(new Models.MessageStruct() { Message = msg, level = level });
}

private void FlushMessageQueue()
{
    if (_messageQueue.IsEmpty) return;
    App.Current.Dispatcher.BeginInvoke(new Action(() =>
    {
        while (_messageQueue.TryDequeue(out var item))
            _eventAggregator.GetEvent<TaskMessageNotification>().Publish(item);
    }));
}
```

**RemoteCommandService.cs**（同样方式）：

```csharp
private static readonly ConcurrentQueue<MessageStruct> _msgQueue = new ConcurrentQueue<MessageStruct>();
private static System.Threading.Timer _msgFlushTimer;
private static IEventAggregator _msgEventAggregator;
private static bool _msgInitialized;

private void SendTaskMessage(string msg, MessageLevel level)
{
    if (!_msgInitialized)
    {
        _msgEventAggregator = _eventAggregator;
        _msgFlushTimer = new System.Threading.Timer(_ => FlushMessageQueue(), null, 200, 200);
        _msgInitialized = true;
    }
    _msgQueue.Enqueue(new Models.MessageStruct() { Message = msg, level = level });
}
```

### 4.2 原理

```
改造前：每次 SendTaskMessage → Dispatcher.Invoke → 等待 UI 线程 → 700-1462ms ✗

改造后：每次 SendTaskMessage → ConcurrentQueue.Enqueue → 0ms ✓
        Timer 200ms → BeginInvoke 一次 → 批量消费队列 → UI 展示 ✓
```

### 4.3 涉及文件

| 文件 | 改动 |
|------|------|
| `Management.cs` | 改 `SendTaskMessage` + 新增 `FlushMessageQueue` |
| `RemoteCommandService.cs` | 改 `SendTaskMessage` + 新增 `FlushMessageQueue` |
| `OptCamera.cs` | 添加 Grab/SetExposure/SetGain 诊断日志（保留用于监控） |
| `OPCuaClientPLC.cs` | 添加读写/轮询诊断日志（保留用于监控） |

### 4.4 修复效果

| 指标 | 修复前 | 修复后 | 改善 |
|------|--------|--------|------|
| SetExp→SetGain 间隙 | 700-1462ms | 0-30ms | **-98%** |
| 单相机总耗时 | 927-1494ms | 231-261ms | **-84%** |
| status write 延迟 | ~1500ms | ~235ms | **-84%** |
| 调用方改动 | — | **0 处** | — |

---

## 5. 附加优化

在排查过程中同步修复了以下问题：

| 问题 | 修复 |
|------|------|
| `PlcCommandTrigger` 为 `async void` | 改为同步包装 + `async Task`，释放 OPC UA 回调线程 |
| `PollingSubscriptionLoopAsync` 连续读抢占 Session | 改为"读完再等待"，给 WriteRequest 留出发送窗口 |
| `GrabImageEx` 的 `Task.Run` 包装确保主流程不阻塞 | 保留 `GrabImageEx` 原始调用方式 |