PLC 状态写入延迟排查报告

1. 问题现象

1.1 现象描述

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

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：

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 线程）：

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

阻塞成因：

Dispatcher.Invoke 需要 UI 线程空闲才能执行委托
UI 线程忙于 Cognex VisionPro 图像渲染、ObservableCollection 数据绑定更新
每个产品周期有 50+ 次 SendTaskMessage 调用
累积阻塞 = 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：

// 新增字段
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（同样方式）：

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` 原始调用方式

PLC写入延迟排查报告.md 8.6 KB History Raw