NLog: Parallel.Foreach without MaxDegreeOfParallelism becomes slow with many long running tasks

I found that one of our applications stopped doing any work. Debugging it showed that all threads were waiting for NLog to log a message.

It looked somthing like this:

Not Flagged		78408	70	Worker Thread	.NET ThreadPool Worker	NLog.dll!NLog.Targets.Wrappers.ConcurrentRequestQueue.WaitForBelowRequestLimit
 	 	 	 	 	 	[External Code]
 	 	 	 	 	 	NLogWait.dll!NLogWait.Worker.ExecuteAsync.AnonymousMethod__0(int _) Line 20
 	 	 	 	 	 	[External Code]


Not Flagged		83588	68	Worker Thread	.NET ThreadPool Worker	System.Private.CoreLib.dll!System.Threading.Monitor.Wait
 	 	 	 	 	 	[External Code]
 	 	 	 	 	 	NLogWait.dll!NLogWait.Worker.ExecuteAsync.AnonymousMethod__0(int _) Line 20
 	 	 	 	 	 	[External Code]

I’ve creted a small repor here: https://github.com/DaveSenn/NLogWait

NLog version:

        <PackageReference Include="NLog" Version="4.7.12" />
        <PackageReference Include="NLog.Extensions.Logging" Version="1.7.4" />
        <PackageReference Include="NLog.Extensions.Hosting" Version="1.7.4" />

Platform: .NET 6

Current NLog config (xml or C#, if relevant)

<?xml version="1.0" encoding="utf-8"?>

<nlog
  xmlns="http://www.nlog-project.org/schemas/NLog.xsd"
  xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
  autoReload="true"
  internalLogFile="C:\Temp\NlogInternalLog.log"
  internalLogToConsole="false"
  internalLogToConsoleError="false"
  internalLogLevel="Warn">

  <variable name="appName" value="MyApp" />
  <variable name="logDirRoot" value="C:\Temp\" />

  <targets>
    <!-- async file target for defaultFile  -->
    <target name="detailLogTarget" xsi:type="AsyncWrapper"  overflowAction="Block" queueLimit="50000"
            batchSize="1000" timeToSleepBetweenBatches="0">
        <target xsi:type="File"
                optimizeBufferReuse="true"
                archiveAboveSize="20971520"
                archiveEvery="None"
                archiveNumbering="Sequence"
                fileAttributes="NotContentIndexed"
                encoding="utf-8"
                writeBom="true"
                lineEnding="LF"
                keepFileOpen="true"
                openFileCacheTimeout="30"
                concurrentWrites="false"
                bufferSize="65536"
                autoFlush="true"
                cleanupFileName="false"
                fileName="${logDirRoot}/${appName}_${machinename}_${assembly-version}_${date:format=yyyy-MM-dd}.log"
                layout="${longdate}  ${pad:padding=5:padCharacter=0:inner=${threadid}}  !${pad:padding=-5:padCharacter= :inner=${level}}  ${message}  [${logger:shortName=true}]  ${event-properties:EventId} ${event-properties:EventId_Id}
${onexception:inner=${newline}${exception:innerFormat=ToString,StackTrace:maxInnerExceptionLevel=20:format=ToString,StackTrace}}">
        </target>
    </target>
    <!--End async file target for defaultFile-->

    <!-- Console target -->
    <target name="consoleAsyncWrapper" xsi:type="AsyncWrapper" overflowAction="Block" queueLimit="50000"
            batchSize="1000" timeToSleepBetweenBatches="0">
      <target xsi:type="ColoredConsole" optimizeBufferReuse="true" detectConsoleAvailable="true" enableAnsiOutput="true"
              layout="${pad:padding=3:padCharacter=0:inner=${threadid}}  ${date:format=ss.ffff}  !${pad:padding=-5:padCharacter= :inner=${level}}  ${message}  [${logger:shortName=true}]
${onexception:inner=${newline}${exception:innerFormat=ToString,StackTrace:maxInnerExceptionLevel=20:format=ToString,StackTrace}}">
      </target>
    </target>
  </targets>

  <!--All logging rules (mapping between loggers and targets)-->
  <rules>
    <logger name="*" minlevel="Debug" writeTo="detailLogTarget"></logger>
    <logger name="*" minlevel="Warn" writeTo="consoleAsyncWrapper"></logger>
  </rules>
</nlog>

About this issue

  • Original URL
  • State: closed
  • Created 3 years ago
  • Reactions: 1
  • Comments: 15 (7 by maintainers)

Most upvoted comments

@ericstj + @jeffhandley It makes sense to mainly focus on the pull-requests. Right now the merged pull-request https://github.com/dotnet/runtime/pull/61931 also points at ver. 6.0.x instead of ver. 6.0.2.

Maybe part of the release-creation/tagging or milestone-closing (Right now the “milestone”-closing + “release”-creation seems a little disconnected with GitHub).

Good catch on that, @snakefoot. As @stephentoub alluded to, we’ve not been disciplined about moving dotnet/runtime issues into the proper milestone once they’re merged into a servicing release. I’ll take a note of that to see if we can incorporate that step into our servicing release processes.