Detecting/Diagnosing Thread Starvation

user_151084 0
Viewed 11012

I am doing some performance/scalability testing of an IIS application that occasionally seems to slow down to a crawl in production. I'm able to reproduce the slowness consistently using NUnit.

CPU and Memory do not spike during the testing, or when the slowness occurs in production. My strong suspicion is that the application is suffering from thread starvation, since it does not appear to be CPU, Memory, I/O, or database access that is causing the bottleneck. I do see signs of what appear to be thread starvation; for example, NLog's async log file writes tend to have long periods of silence followed by bursts of activity with older time stamps (i.e. a lower-priority thread is waiting for threads to free up in order to write).

What steps can I take to definitively determine that the application is indeed thread starved, and (assuming that is the case) pinpoint the exact areas of the system that are causing the problem?

Edit

I neglected to mention that almost all the code is synchronous (it's a legacy system).

starvation threadpool iis .net c#
2 Answers

I came up with this based on the above

using System;
using System.Threading;
using System.Timers;
using log4net;

using Timer = System.Timers.Timer;

namespace somewhere
{
    public class ThreadStatsLogger : IDisposable
    {
        private const int DEPLETION_WARN_LEVEL = 10;
        private const int HISTERESIS_LEVEL = 10;

    private const double SAMPLE_RATE_MILLISECONDS = 500;
    private bool _workerThreadWarned = false;
    private bool _ioThreadWarned = false;
    private bool _minWorkerThreadLevelWarned = false;
    private bool _minIoThreadLevelWarned = false;

    private readonly int _maxWorkerThreadLevel;
    private readonly int _maxIoThreadLevel;
    private readonly int _minWorkerThreadLevel;
    private readonly int _minWorkerThreadLevelRecovery;
    private readonly int _minIoThreadLevel;
    private readonly int _minIoThreadLevelRecovery;
    private Timer _timer;

    private static readonly ILog _logger = LogManager.GetLogger(System.Reflection.MethodBase.GetCurrentMethod().DeclaringType);

    public ThreadStatsLogger()
    {

        _timer = new Timer
        {
            AutoReset = true,
            Interval = SAMPLE_RATE_MILLISECONDS,
        };

        _timer.Elapsed += TimerElasped;
        _timer.Start();
        ThreadPool.GetMinThreads(out _minWorkerThreadLevel, out _minIoThreadLevel);
        ThreadPool.GetMaxThreads(out _maxWorkerThreadLevel, out _maxIoThreadLevel);
        ThreadPool.GetAvailableThreads(out int workerAvailable, out int ioAvailable);

        _logger.InfoFormat("Thread statistics at startup: minimum worker:{0} io:{1}", _minWorkerThreadLevel, _minIoThreadLevel );
        _logger.InfoFormat("Thread statistics at startup: maximum worker:{0} io:{1}", _maxWorkerThreadLevel, _maxIoThreadLevel);
        _logger.InfoFormat("Thread statistics at startup: available worker:{0} io:{1}", workerAvailable, ioAvailable);

        _minWorkerThreadLevelRecovery = (_minWorkerThreadLevel * 3) / 4;
        _minIoThreadLevelRecovery = (_minIoThreadLevel * 3) / 4;
        if (_minWorkerThreadLevelRecovery == _minWorkerThreadLevel) _minWorkerThreadLevelRecovery = _minWorkerThreadLevel - 1;
        if (_minIoThreadLevelRecovery == _minIoThreadLevel) _minIoThreadLevelRecovery = _minIoThreadLevel - 1;
    }

    private void TimerElasped(object sender, ElapsedEventArgs e)
    {

        ThreadPool.GetAvailableThreads(out int availableWorkerThreads, out int availableIoThreads);

        var activeWorkerThreads = _maxWorkerThreadLevel - availableWorkerThreads;
        var activeIoThreads = _maxIoThreadLevel - availableIoThreads;

        _logger.InfoFormat("Thread statistics: active worker:{0} io:{1}", activeWorkerThreads, activeIoThreads);

        if (activeWorkerThreads > _minWorkerThreadLevel && !_minWorkerThreadLevelWarned)
        {
            _logger.InfoFormat("Thread statistics WARN active worker threads above minimum {0}:{1}", activeWorkerThreads, _minWorkerThreadLevel);
            _minWorkerThreadLevelWarned = !_minWorkerThreadLevelWarned;
        }
        if (activeWorkerThreads < _minWorkerThreadLevelRecovery && _minWorkerThreadLevelWarned)
        {
            _logger.InfoFormat("Thread statistics RECOVERY active worker threads below minimum {0}:{1}", activeWorkerThreads, _minWorkerThreadLevel);
            _minWorkerThreadLevelWarned = !_minWorkerThreadLevelWarned;
        }

        if (activeIoThreads > _minIoThreadLevel && !_minIoThreadLevelWarned)
        {
            _logger.InfoFormat("Thread statistics WARN active io threads above minimum {0}:{1}", activeIoThreads, _minIoThreadLevel);
            _minIoThreadLevelWarned = !_minIoThreadLevelWarned;
        }
        if (activeIoThreads < _minIoThreadLevelRecovery && _minIoThreadLevelWarned)
        {
            _logger.InfoFormat("Thread statistics RECOVERY active io threads below minimum {0}:{1}", activeIoThreads, _minIoThreadLevel);
            _minIoThreadLevelWarned = !_minIoThreadLevelWarned;
        }

        if (availableWorkerThreads < DEPLETION_WARN_LEVEL && !_workerThreadWarned)
        {
            _logger.InfoFormat("Thread statistics WARN available worker threads below warning level {0}:{1}", availableWorkerThreads, DEPLETION_WARN_LEVEL);
            _workerThreadWarned = !_workerThreadWarned;
        }

        if (availableWorkerThreads > (DEPLETION_WARN_LEVEL + HISTERESIS_LEVEL) && _workerThreadWarned)
        {
            _logger.InfoFormat("Thread statistics RECOVERY available worker thread recovery {0}:{1}", availableWorkerThreads, DEPLETION_WARN_LEVEL);
            _workerThreadWarned = !_workerThreadWarned;
        }

        if (availableIoThreads < DEPLETION_WARN_LEVEL && !_ioThreadWarned)
        {
            _logger.InfoFormat("Thread statistics WARN available io threads below warning level {0}:{1}", availableIoThreads, DEPLETION_WARN_LEVEL);
            _ioThreadWarned = !_ioThreadWarned;
        }

        if (availableIoThreads > (DEPLETION_WARN_LEVEL + HISTERESIS_LEVEL) && _ioThreadWarned)
        {
            _logger.InfoFormat("Thread statistics RECOVERY available io thread recovery {0}:{1}", availableIoThreads, DEPLETION_WARN_LEVEL);
            _ioThreadWarned = !_ioThreadWarned;
        }
    }

    public void Dispose()
    {
        if (_timer == null) return;
        _timer.Close();
        _timer.Dispose();
        _timer = null;
    }
}

}

user_26688690
Related