[jira] [Commented] (LOG4NET-454) Intermittent severe slowdown with RollingFileAppender+MinimalLock

["Dominik Psenner (JIRA)" <ji...@apache.org>]

    [ https://issues.apache.org/jira/browse/LOG4NET-454?page=com.atlassian.jira.plugin.system.issuetabpanels:comment-tabpanel&focusedCommentId=14342877#comment-14342877 ] 

Dominik Psenner commented on LOG4NET-454:
-----------------------------------------

This all sounds interesting. MinimalLock opens/closes the file whenever logs have to be written. On the other hand, ExclusiveLock keeps the logfile opened. So my assumption is that the opening of a logfile takes longer than expected for some files and thus the ExclusiveLock mode may suffer from the "performance penalty" just once in its lifetime. Why there should be a performance penalty at all is beyond my imagination. Since you are able to reproduce this issue, would you mind running log4net from source and add several "checkpoints" with timings within the method "protected Stream CreateStream(string filename, bool append, FileShare fileShare)"? If I'm right then you should be able to hunt down the slow invoke quite easily. We have three candidates there: SecurityContext.Impersonate(...), Directory.CreateDirectory(...) and new FileStream(...). Otherwise you will have to post the logfiles and pray that we can reproduce the issue. :-)

> Intermittent severe slowdown with RollingFileAppender+MinimalLock
> -----------------------------------------------------------------
>
>                 Key: LOG4NET-454
>                 URL: https://issues.apache.org/jira/browse/LOG4NET-454
>             Project: Log4net
>          Issue Type: Bug
>          Components: Appenders
>    Affects Versions: 1.2.13
>         Environment: ASP.NET MVC 5.2.2 Application, Windows 7 Professional
>            Reporter: Chuck Felish
>
> Using RollingFileAppender with MinimalLock we found an extreme slowdown in the processing of our application requests (from 300ms to up to 15s in some cases) which was resolved when we deleted our log files. We also found that changing the lock to Exclusive resolved the issue.
> Interestingly file content seemed to be related, but not file size. When I took the contents of a colleague's log file and pasted them into my own log file the slowness issue appeared again. I then tried deleting about half the contents and then causing the file to grow to larger than the original size but the issue did not return. Pasting the original contents back into the file caused the performance issue to return.
> While Exclusive lock has resolved our issue for now, it's quite unexpected that file contents would affect performance at all, and that the issue is does not consistently reproduce even though configuration is unchanged.
> I'm happy to demonstrate and/or share our problematic log files with you to facilitate the resolution of this issue.
> Our configuration is as follows:
>     <appender name="RollingFile" type="log4net.Appender.RollingFileAppender">
>         <file type="log4net.Util.PatternString" value="Logs\%property{ExecutableName}_%env{COMPUTERNAME}.log" />
>         <lockingModel type="log4net.Appender.FileAppender+MinimalLock" />
>         <appendToFile value="true" />
>         <rollingStyle value="Size" />
>         <maximumFileSize value="5MB" />
>         <maxSizeRollBackups value="50" />
>         <preserveLogFileNameExtension value="true" />
>         <layout type="log4net.Layout.PatternLayout">
>             <conversionPattern value="%d{yyyy-MM-dd HH:mm:ss.fff} [%-5level][%5thread] %logger - %m%n" />
>         </layout>
>     </appender>
>     <root>
>         <!-- NOTE:  This is overriden programatically by Log4NetConfig.cs -->
>         <level value="ALL" />
> <!--        <appender-ref ref="ColorConsole" />-->
>         <appender-ref ref="RollingFile" />
>     </root>



--
This message was sent by Atlassian JIRA
(v6.3.4#6332)