Hi! Thanks for reporting this feature/bug/question!
Please keep / fill in the relevant info from this template so that we can help you as best as possible.
QUESTIONS are preferred on StackOverflow. You could expect a faster response there (but do include all the info below). Use the tag "nlog" https://stackoverflow.com/questions/ask
For .NET Core users, please check the platform support: https://github.com/NLog/NLog/wiki/platform-support
NLog version: 4.6.3
Platform: .Net 4.7.2/ .NET Core 2
Current NLog config (xml or C#, if relevant)
It happen when set <default-wrapper xsi:type="AsyncWrapper" overflowAction="Block" forceLockingQueue="false" />(or netcore2.0 without forceLockingQueue). And can be reproducted with the below code.
var queue = new NLog.Targets.Wrappers.ConcurrentRequestQueue(10, NLog.Targets.Wrappers.AsyncTargetWrapperOverflowAction.Block);
for (var j = 0; j < 3; ++j)
{
int cur = j;
_ = Task.Run(() =>
{
for (int i = 0; i < 20; ++i)
{
queue.Enqueue(default(NLog.Common.AsyncLogEventInfo));
Console.WriteLine($"Thread {cur}: PostEnqueue {i + 1}");
}
});
}
Task.Run(() =>
{
Thread.Sleep(1000);
int left = 20 * 3;
while (left > 0)
{
var tmp = queue.DequeueBatch(3);
left -= tmp.Length;
if (tmp.Length != 0)
Console.WriteLine($"DequeueBatch left={left}");
}
Console.WriteLine("Finished");
}).Wait();
You can see some threads are block on line133(Monitor.Enter(_logEventInfoQueue);), but the queue is empty at that time. Seems Monitor.Wait() should not change the value of lockTaken at line141.
|
private long WaitForBelowRequestLimit() |
|
{ |
|
long currentCount; |
|
bool lockTaken = false; |
|
try |
|
{ |
|
// Attempt to yield using SpinWait |
|
currentCount = TrySpinWaitForLowerCount(); |
|
|
|
// If yield did not help, then wait on a lock |
|
while (currentCount > RequestLimit) |
|
{ |
|
if (!lockTaken) |
|
{ |
|
InternalLogger.Debug("Blocking because the overflow action is Block..."); |
|
Monitor.Enter(_logEventInfoQueue); |
|
lockTaken = true; |
|
InternalLogger.Trace("Entered critical section."); |
|
} |
|
else |
|
{ |
|
InternalLogger.Debug("Blocking because the overflow action is Block..."); |
|
if (!Monitor.Wait(_logEventInfoQueue, 100)) |
|
lockTaken = false; |
|
else |
|
InternalLogger.Trace("Entered critical section."); |
|
} |
|
currentCount = Interlocked.Read(ref _count); |
|
} |
|
|
|
if (lockTaken) |
|
{ |
|
Monitor.PulseAll(_logEventInfoQueue); |
|
} |
|
} |
|
finally |
|
{ |
|
if (lockTaken) |
|
Monitor.Exit(_logEventInfoQueue); |
|
} |
|
|
|
return currentCount; |
|
} |
- What is the current result?
Still block even if the queue is empty at that time.
- What is the expected result?
No block after the queue be empty.
- Did you checked the Internal log?
- Please post full exception details (message, stacktrace, inner exceptions)
- Are there any workarounds? yes/no
- Is there a version in which it did work?
- Can you help us by writing an unit test?
Hi! Thanks for reporting this feature/bug/question!
Please keep / fill in the relevant info from this template so that we can help you as best as possible.
QUESTIONS are preferred on StackOverflow. You could expect a faster response there (but do include all the info below). Use the tag "nlog" https://stackoverflow.com/questions/ask
For .NET Core users, please check the platform support: https://github.com/NLog/NLog/wiki/platform-support
NLog version: 4.6.3
Platform: .Net 4.7.2/ .NET Core 2
Current NLog config (xml or C#, if relevant)
It happen when set
<default-wrapper xsi:type="AsyncWrapper" overflowAction="Block" forceLockingQueue="false" />(or netcore2.0 withoutforceLockingQueue). And can be reproducted with the below code.You can see some threads are block on line133(
Monitor.Enter(_logEventInfoQueue);), but the queue is empty at that time. SeemsMonitor.Wait()should not change the value oflockTakenat line141.NLog/src/NLog/Targets/Wrappers/ConcurrentRequestQueue.cs
Lines 118 to 160 in 610f368
Still block even if the queue is empty at that time.
No block after the queue be empty.