异步执行：排查两条日志语句间的间歇性延迟问题

应用背景 #

基于NetStandard2.0用C#开发了一个多线程库，同一物理机或虚拟机上最多会有40个工具进程同时调用该库。

部署环境 #

Windows Server

问题现象 #

库中一段代码会间歇性出现阻塞：正常执行仅需数毫秒，但有时ToolCheckLayer输出的KeepAlive is working...日志，与MessageBus输出的Creating listener...日志之间会出现长时间延迟（最近一次达45秒）。问题代码位于CheckAsync方法的using语句处：

public class ToolCheckLayer
{
    private async Task<bool> CheckAsync(CancellationToken cancellationToken)
    {
        Logger?.Info("KeepAlive is working...");
        using (var messageListener = await _bus.CreateListenerAsync(cancellationToken)
            .ConfigureAwait(false))
        {
            // 业务操作
            return true;
        }
        return false;
    }
}

核心代码片段 #

与总线监听器创建相关的代码如下：

public class MessageBus
{
    private readonly ILogger _logger;
    private readonly SemaphoreSlim _listenerSemaphore;        
  
    public class MessageBusListener : IDisposable
    {
        private readonly ILogger _logger;        
        private readonly bool _privileged;        
        private readonly BufferBlock<MessageBase> _queue;        

        public MessageBusListener(ILogger logger, bool privileged,
            Action disposeAction)
        {
            _logger = logger;
            _privileged = privileged;
            _queue = new BufferBlock<MessageBase>();
        }

        // 其他相关函数...
    }

    public MessageBus(ILogger logger, int maxConcurrentListeners)
    {
        _logger = logger;
        _listenerSemaphore = new SemaphoreSlim(maxConcurrentListeners);
    }

    public async Task<MessageBusListener> CreateListenerAsync(
        CancellationToken cancellationToken)
    {
        _logger?.Debug("Creating listener...");        
        await _listenerSemaphore.WaitAsync(cancellationToken);

        var listener = new MessageBusListener(_logger, privileged: false, () =>
        {
            _listenerSemaphore.Release();
        });
        
        // 监听器初始化操作        

        return listener;
    }
}

已开展的排查工作 #

• 问题为偶发，通常系统平稳运行数周或数月后随机出现
• 阻塞期间未检测到CPU、内存或I/O资源瓶颈
• 最新观测：某次故障中24个工具进程全部出现阻塞，所有进程的CreateListenerAsync调用都被阻塞至10:21:00.01xx这个时间点后才同时解除，阻塞时长约45秒。Zabbix监控数据显示CPU利用率3%，内存占用40%，无异常指标。

内容的提问来源于stack exchange，提问作者KhanH