Performance improvements for file logging (#9655)

Author: mathewc

src/WebJobs.Script/Diagnostics/FileLogger.cs

@@ -92,14 +92,8 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state, Except
             try
             {
                 _fileWriter.AppendLine(formattedMessage);
-
-                // flush errors immediately
-                if (logLevel == LogLevel.Error || exception != null)
-                {
-                    _fileWriter.Flush();
-                }
             }
-            catch (Exception)
+            catch (Exception ex) when (!ex.IsFatal())
             {
                 // Make sure the Logger doesn't throw if there are Exceptions (disk full, etc).
             }

src/WebJobs.Script/Diagnostics/FileWriter.cs

@@ -30,7 +30,7 @@ internal class FileWriter : IFileWriter, IDisposable
         private Timer _flushTimer;
         private ConcurrentQueue<string> _logBuffer = new ConcurrentQueue<string>();
 
-        public FileWriter(string logFilePath)
+        public FileWriter(string logFilePath, int flushIntervalMs = LogFlushIntervalMs)
         {
             _logFilePath = logFilePath;
             _instanceId = GetInstanceId();
@@ -39,8 +39,8 @@ public FileWriter(string logFilePath)
             // start a timer to flush accumulated logs in batches
             _flushTimer = new Timer
             {
-                AutoReset = true,
-                Interval = LogFlushIntervalMs
+                AutoReset = false,
+                Interval = flushIntervalMs
             };
             _flushTimer.Elapsed += OnFlushLogs;
             _flushTimer.Start();
@@ -171,7 +171,14 @@ public void AppendLine(string line)
 
         private void OnFlushLogs(object sender, ElapsedEventArgs e)
         {
-            Flush();
+            try
+            {
+                Flush();
+            }
+            finally
+            {
+                _flushTimer.Start();
+            }
         }
 
         /// <summary>

test/WebJobs.Script.Tests/Diagnostics/FileWriterTests.cs

@@ -182,6 +182,28 @@ public void Flush_ReusesLastFile()
             Assert.Equal(3, fileLines.Length);
         }
 
+        [Fact]
+        public async Task LogsAreFlushedOnTimer()
+        {
+            FileWriter fileWriter = new FileWriter(_logFilePath, flushIntervalMs: 10);
+
+            // timer should elapse 50 times during this test
+            int numLogs = 100;
+            for (int i = 0; i < numLogs; i++)
+            {
+                fileWriter.AppendLine($"Test message {Thread.CurrentThread.ManagedThreadId} {i}");
+                await Task.Delay(5);
+            }
+
+            var directory = new DirectoryInfo(_logFilePath);
+            int count = directory.EnumerateFiles().Count();
+            Assert.Equal(1, count);
+
+            string logFile = directory.EnumerateFiles().First().FullName;
+            string[] fileLines = File.ReadAllLines(logFile);
+            Assert.Equal(numLogs, fileLines.Length);
+        }
+
         [Fact]
         public async Task Flush_ThrottlesLogs()
         {