File logging perf optimizations

mathewc · mathewc · commit 60c80e0a3b02 · 2016-03-16T18:23:37.000-07:00
diff --git a/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs b/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs
@@ -127,6 +127,10 @@ protected override Collection<ParameterDescriptor> GetFunctionParameters(IFuncti
                     }
                 }
 
+                // Add any additional common System parameters
+                // Add ExecutionContext to provide access to InvocationId, etc.
+                descriptors.Add(new ParameterDescriptor("context", typeof(ExecutionContext)));
+
                 return descriptors;
             }
             catch (AggregateException exc)
diff --git a/src/WebJobs.Script/Description/CSharp/CSharpFunctionInvoker.cs b/src/WebJobs.Script/Description/CSharp/CSharpFunctionInvoker.cs
@@ -171,19 +171,34 @@ private void RestorePackages()
 
         public override async Task Invoke(object[] parameters)
         {
+            // Separate system parameters from the actual method parameters
+            object[] originalParameters = parameters;
+            MethodInfo function = await GetFunctionTargetAsync();
+            int actualParameterCount = function.GetParameters().Length;
+            object[] systemParameters = parameters.Skip(actualParameterCount).ToArray();
+            parameters = parameters.Take(actualParameterCount).ToArray();
+            
+            ExecutionContext functionExecutionContext = (ExecutionContext)systemParameters[0];
+            string invocationId = functionExecutionContext.InvocationId.ToString();
+
             FunctionStartedEvent startedEvent = new FunctionStartedEvent(Metadata);
             _metrics.BeginEvent(startedEvent);
 
             try
             {
-                TraceWriter.Verbose("Function started");
+                TraceWriter.Verbose(string.Format("Function started (Id={0})", invocationId));
 
                 parameters = ProcessInputParameters(parameters);
 
-                MethodInfo function = await GetFunctionTargetAsync();
-
                 object functionResult = function.Invoke(null, parameters);
 
+                // after the function executes, we have to copy values back into the original
+                // array to ensure object references are maintained (since we took a copy above)
+                for (int i = 0; i < parameters.Length; i++)
+                {
+                    originalParameters[i] = parameters[i];
+                }
+
                 if (functionResult is Task)
                 {
                     functionResult = await((Task)functionResult).ContinueWith(t => GetTaskResult(t));
@@ -194,7 +209,7 @@ public override async Task Invoke(object[] parameters)
                     _resultProcessor(function, parameters, functionResult);
                 }
 
-                TraceWriter.Verbose("Function completed (Success)");
+                TraceWriter.Verbose(string.Format("Function completed (Success, Id={0})", invocationId));
             }
             catch (Exception ex)
             {
@@ -203,7 +218,7 @@ public override async Task Invoke(object[] parameters)
                 startedEvent.Success = false;
                 TraceWriter.Error(ex.Message, ex);
 
-                TraceWriter.Verbose("Function completed (Failure)");
+                TraceWriter.Verbose(string.Format("Function completed (Failure, Id={0})", invocationId));
                 throw;
             }
             finally
diff --git a/src/WebJobs.Script/Description/NodeFunctionInvoker.cs b/src/WebJobs.Script/Description/NodeFunctionInvoker.cs
@@ -95,18 +95,19 @@ public override async Task Invoke(object[] parameters)
             TraceWriter traceWriter = (TraceWriter)parameters[1];
             IBinder binder = (IBinder)parameters[2];
             ExecutionContext functionExecutionContext = (ExecutionContext)parameters[3];
+            string invocationId = functionExecutionContext.InvocationId.ToString();
 
             FunctionStartedEvent startedEvent = new FunctionStartedEvent(Metadata);
             _metrics.BeginEvent(startedEvent);
 
             try
             {
-                TraceWriter.Verbose(string.Format("Function started"));
+                TraceWriter.Verbose(string.Format("Function started (Id={0})", invocationId));
 
                 var scriptExecutionContext = CreateScriptExecutionContext(input, traceWriter, TraceWriter, binder, functionExecutionContext);
 
                 Dictionary<string, string> bindingData = GetBindingData(input, binder, _inputBindings, _outputBindings);
-                bindingData["InvocationId"] = functionExecutionContext.InvocationId.ToString();
+                bindingData["InvocationId"] = invocationId;
                 scriptExecutionContext["bindingData"] = bindingData;
 
                 await ProcessInputBindingsAsync(binder, scriptExecutionContext, bindingData);
@@ -115,13 +116,13 @@ public override async Task Invoke(object[] parameters)
 
                 await ProcessOutputBindingsAsync(_outputBindings, input, binder, bindingData, scriptExecutionContext, functionResult);
 
-                TraceWriter.Verbose(string.Format("Function completed (Success)"));
+                TraceWriter.Verbose(string.Format("Function completed (Success, Id={0})", invocationId));
             }
             catch (Exception ex)
             {
                 startedEvent.Success = false;
                 TraceWriter.Error(ex.Message, ex);
-                TraceWriter.Verbose(string.Format("Function completed (Failure)"));
+                TraceWriter.Verbose(string.Format("Function completed (Failure, Id={0})", invocationId));
                 throw;
             }
             finally
diff --git a/src/WebJobs.Script/Description/ScriptFunctionInvoker.cs b/src/WebJobs.Script/Description/ScriptFunctionInvoker.cs
@@ -90,6 +90,7 @@ internal async Task ExecuteScriptAsync(string path, string arguments, object[] i
             TraceWriter traceWriter = (TraceWriter)invocationParameters[1];
             IBinder binder = (IBinder)invocationParameters[2];
             ExecutionContext functionExecutionContext = (ExecutionContext)invocationParameters[3];
+            string invocationId = functionExecutionContext.InvocationId.ToString();
 
             FunctionStartedEvent startedEvent = new FunctionStartedEvent(Metadata);
             _metrics.BeginEvent(startedEvent);
@@ -109,9 +110,8 @@ internal async Task ExecuteScriptAsync(string path, string arguments, object[] i
                 }
             }
 
-            TraceWriter.Verbose(string.Format("Function started"));
+            TraceWriter.Verbose(string.Format("Function started (Id={0})", invocationId));
 
-            string invocationId = functionExecutionContext.InvocationId.ToString();
             string workingDirectory = Path.GetDirectoryName(_scriptFilePath);
             string functionInstanceOutputPath = Path.Combine(Path.GetTempPath(), "Functions", "Binding", invocationId);
 
@@ -140,7 +140,7 @@ internal async Task ExecuteScriptAsync(string path, string arguments, object[] i
 
                 string error = process.StandardError.ReadToEnd();
                 TraceWriter.Error(error);
-                TraceWriter.Verbose(string.Format("Function completed (Failure)"));
+                TraceWriter.Verbose(string.Format("Function completed (Failure, Id={0})", invocationId));
                 throw new ApplicationException(error);
             }
 
@@ -150,7 +150,7 @@ internal async Task ExecuteScriptAsync(string path, string arguments, object[] i
 
             await ProcessOutputBindingsAsync(functionInstanceOutputPath, _outputBindings, input, binder, bindingData);
 
-            TraceWriter.Verbose(string.Format("Function completed (Success)"));
+            TraceWriter.Verbose(string.Format("Function completed (Success, Id={0})", invocationId));
         }
 
         private void InitializeEnvironmentVariables(Dictionary<string, string> environmentVariables, string functionInstanceOutputPath, object input, Collection<FunctionBinding> outputBindings, ExecutionContext context)
diff --git a/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs b/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs
@@ -184,6 +184,11 @@ protected virtual void Dispose(bool disposing)
                     {
                         _fileWatcher.Dispose();
                     }
+
+                    if (TraceWriter != null && TraceWriter is IDisposable)
+                    {
+                        ((IDisposable)TraceWriter).Dispose();
+                    }
                 }
 
                 _disposed = true;
diff --git a/src/WebJobs.Script/FileTraceWriter.cs b/src/WebJobs.Script/FileTraceWriter.cs
@@ -2,21 +2,29 @@
 // Licensed under the MIT License. See License.txt in the project root for license information.
 
 using System;
+using System.Collections.Concurrent;
 using System.Diagnostics;
 using System.Globalization;
 using System.IO;
 using System.Linq;
+using System.Text;
+using System.Timers;
 using Microsoft.Azure.WebJobs.Host;
 
 namespace Microsoft.Azure.WebJobs.Script
 {
-    public class FileTraceWriter : TraceWriter
+    public class FileTraceWriter : TraceWriter, IDisposable
     {
         private const long MaxLogFileSizeBytes = 5 * 1024 * 1024;
+        private const int LogFlushIntervalMs = 1000;
         private readonly string _logFilePath;
         private readonly string _instanceId;
         private static object _syncLock = new object();
         private FileInfo _currentLogFileInfo;
+        private bool _disposed = false;
+
+        private Timer _flushTimer;
+        private ConcurrentQueue<string> _logBuffer = new ConcurrentQueue<string>();
 
         public FileTraceWriter(string logFilePath, TraceLevel level) : base(level)
         {
@@ -39,6 +47,62 @@ public FileTraceWriter(string logFilePath, TraceLevel level) : base(level)
             {
                 SetNewLogFile();
             }
+
+            // start a timer to flush accumulated logs in batches
+            _flushTimer = new Timer
+            {
+                AutoReset = true,
+                Interval = LogFlushIntervalMs
+            };
+            _flushTimer.Elapsed += OnFlushLogs;
+            _flushTimer.Start();
+        }
+
+        public void FlushToFile()
+        {
+            if (_logBuffer.Count == 0)
+            {
+                return;
+            }
+
+            // snapshot the current set of buffered logs
+            // and set a new bag
+            ConcurrentQueue<string> currentBuffer = _logBuffer;
+            _logBuffer = new ConcurrentQueue<string>();
+
+            // concatenate all lines into one string
+            StringBuilder sb = new StringBuilder();
+            string line = null;
+            while (currentBuffer.TryDequeue(out line))
+            {
+                sb.AppendLine(line);
+            }
+
+            // write all lines in a single file operation
+            string contents = sb.ToString();
+            try
+            {
+                lock (_syncLock)
+                {
+                    File.AppendAllText(_currentLogFileInfo.FullName, contents);
+                }
+            }
+            catch (DirectoryNotFoundException)
+            {
+                // need to handle cases where log file directories might
+                // have been deleted from underneath us
+                Directory.CreateDirectory(_logFilePath);
+                lock (_syncLock)
+                {
+                    File.AppendAllText(_currentLogFileInfo.FullName, contents);
+                }
+            }
+
+            _currentLogFileInfo.Refresh();
+            if (_currentLogFileInfo.Length > MaxLogFileSizeBytes)
+            {
+                SetNewLogFile();
+            }
         }
 
         public override void Trace(TraceEvent traceEvent)
@@ -72,42 +136,47 @@ public override void Trace(TraceEvent traceEvent)
             }
         }
 
-        protected virtual void AppendLine(string line)
+        protected virtual void Dispose(bool disposing)
         {
-            if (line == null)
-            {
-                return;
-            }
-
-            // TODO: figure out the right log file format
-            line = string.Format(CultureInfo.InvariantCulture, "{0} {1}\r\n", DateTime.Now.ToString("s", CultureInfo.InvariantCulture), line.Trim());
-
-            // TODO: optimize this locking
-            try
-            {
-                lock (_syncLock)
-                {
-                    File.AppendAllText(_currentLogFileInfo.FullName, line);
-                }
-            }
-            catch (DirectoryNotFoundException)
+            if (!_disposed)
             {
-                // need to handle cases where log file directories might
-                // have been deleted from underneath us
-                Directory.CreateDirectory(_logFilePath);
-                lock (_syncLock)
+                if (disposing)
                 {
-                    File.AppendAllText(_currentLogFileInfo.FullName, line);
+                    if (_flushTimer != null)
+                    {
+                        _flushTimer.Dispose();
+                    }
+
+                    // ensure any remaining logs are flushed
+                    FlushToFile();
                 }
+
+                _disposed = true;
             }
+        }
 
-            // TODO: Need to optimize this, so we only do the check every
-            // so often
-            _currentLogFileInfo.Refresh();
-            if (_currentLogFileInfo.Length > MaxLogFileSizeBytes)
+        public void Dispose()
+        {
+            Dispose(true);
+            GC.SuppressFinalize(this);
+        }
+
+        protected virtual void AppendLine(string line)
+        {
+            if (line == null)
             {
-                SetNewLogFile();
+                return;
             }
+
+            // add the line to the current buffer batch, which is flushed
+            // on a timer
+            line = string.Format(CultureInfo.InvariantCulture, "{0} {1}", DateTime.Now.ToString("yyyy-MM-ddTHH:mm:ss.fff", CultureInfo.InvariantCulture), line.Trim());
+            _logBuffer.Enqueue(line);
+        }
+
+        private void OnFlushLogs(object sender, ElapsedEventArgs e)
+        {
+            FlushToFile();
         }
 
         private void SetNewLogFile()
diff --git a/src/WebJobs.Script/GlobalSuppressions.cs b/src/WebJobs.Script/GlobalSuppressions.cs
@@ -51,4 +51,6 @@
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Maintainability", "CA1502:AvoidExcessiveComplexity", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Binding.HttpBinding.#AddResponseHeader(System.Net.Http.HttpResponseMessage,System.Collections.Generic.KeyValuePair`2<System.String,Newtonsoft.Json.Linq.JToken>)")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration.#Active")]
 [assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2227:CollectionPropertiesShouldBeReadOnly", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration.#Functions")]
-[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Description.FunctionValueLoader.#Create(System.Func`2<System.Threading.CancellationToken,System.Reflection.MethodInfo>)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Description.FunctionValueLoader.#Create(System.Func`2<System.Threading.CancellationToken,System.Reflection.MethodInfo>)")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.FileTraceWriter.#.ctor(System.String,System.Diagnostics.TraceLevel)", Justification = "Disposed in IDisposable implementation.")]
+[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Description.ScriptFunctionInvokerBase.#CreateTraceWriter(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,System.String)", Justification = "Disposed in IDisposable implementation.")]
diff --git a/src/WebJobs.Script/Host/ScriptHost.cs b/src/WebJobs.Script/Host/ScriptHost.cs
@@ -644,6 +644,11 @@ protected override void Dispose(bool disposing)
                 }
 
                 _restartEvent.Dispose();
+
+                if (TraceWriter != null && TraceWriter is IDisposable)
+                {
+                    ((IDisposable)TraceWriter).Dispose();
+                }
             }
         }
     }
diff --git a/test/WebJobs.Script.Tests/FileTraceWriterTests.cs b/test/WebJobs.Script.Tests/FileTraceWriterTests.cs
@@ -54,6 +54,8 @@ private void WriteLogs(string logFilePath, int numLogs)
             {
                 traceWriter.Verbose(string.Format("Test message {0} {1}", Thread.CurrentThread.ManagedThreadId, i));
             }
+
+            traceWriter.FlushToFile();
         }
     }
 }

Original file line number	Diff line number	Diff line change
`@@ -127,6 +127,10 @@ protected override Collection<ParameterDescriptor> GetFunctionParameters(IFuncti`
`127`	`127`	`}`
`128`	`128`	`}`
`129`	`129`
	`130`	`+ // Add any additional common System parameters`
	`131`	`+ // Add ExecutionContext to provide access to InvocationId, etc.`
	`132`	`+ descriptors.Add(new ParameterDescriptor("context", typeof(ExecutionContext)));`
	`133`	`+`
`130`	`134`	`return descriptors;`
`131`	`135`	`}`
`132`	`136`	`catch (AggregateException exc)`
Original file line number	Diff line number	Diff line change
`@@ -184,6 +184,11 @@ protected virtual void Dispose(bool disposing)`
`184`	`184`	`{`
`185`	`185`	`_fileWatcher.Dispose();`
`186`	`186`	`}`
	`187`	`+`
	`188`	`+ if (TraceWriter != null && TraceWriter is IDisposable)`
	`189`	`+ {`
	`190`	`+ ((IDisposable)TraceWriter).Dispose();`
	`191`	`+ }`
`187`	`192`	`}`
`188`	`193`
`189`	`194`	`_disposed = true;`
Original file line number	Diff line number	Diff line change
`@@ -644,6 +644,11 @@ protected override void Dispose(bool disposing)`
`644`	`644`	`}`
`645`	`645`
`646`	`646`	`_restartEvent.Dispose();`
	`647`	`+`
	`648`	`+ if (TraceWriter != null && TraceWriter is IDisposable)`
	`649`	`+ {`
	`650`	`+ ((IDisposable)TraceWriter).Dispose();`
	`651`	`+ }`
`647`	`652`	`}`
`648`	`653`	`}`
`649`	`654`	`}`
Original file line number	Diff line number	Diff line change
`@@ -54,6 +54,8 @@ private void WriteLogs(string logFilePath, int numLogs)`
`54`	`54`	`{`
`55`	`55`	`traceWriter.Verbose(string.Format("Test message {0} {1}", Thread.CurrentThread.ManagedThreadId, i));`
`56`	`56`	`}`
	`57`	`+`
	`58`	`+ traceWriter.FlushToFile();`
`57`	`59`	`}`
`58`	`60`	`}`
`59`	`61`	`}`