From 60c80e0a3b025edb6b954c2eb807421ce675fe6a Mon Sep 17 00:00:00 2001 From: Mathew Charles Date: Wed, 16 Mar 2016 17:58:14 -0700 Subject: [PATCH] File logging perf optimizations --- .../CSharpFunctionDescriptionProvider.cs | 4 + .../CSharp/CSharpFunctionInvoker.cs | 25 +++- .../Description/NodeFunctionInvoker.cs | 9 +- .../Description/ScriptFunctionInvoker.cs | 8 +- .../Description/ScriptFunctionInvokerBase.cs | 5 + src/WebJobs.Script/FileTraceWriter.cs | 127 ++++++++++++++---- src/WebJobs.Script/GlobalSuppressions.cs | 4 +- src/WebJobs.Script/Host/ScriptHost.cs | 5 + .../FileTraceWriterTests.cs | 2 + 9 files changed, 146 insertions(+), 43 deletions(-) diff --git a/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs b/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs index 045be0f7a2..38f9c5ea38 100644 --- a/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs +++ b/src/WebJobs.Script/Description/CSharp/CSharpFunctionDescriptionProvider.cs @@ -127,6 +127,10 @@ protected override Collection 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 index 164e9daf7a..4e9f05a025 100644 --- 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 index d941d94868..031f3bc51e 100644 --- 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 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 index b094c9d0c3..33ac7e1499 100644 --- 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 environmentVariables, string functionInstanceOutputPath, object input, Collection outputBindings, ExecutionContext context) diff --git a/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs b/src/WebJobs.Script/Description/ScriptFunctionInvokerBase.cs index 3404efd98d..ae41d2a35a 100644 --- 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 index 83cd3b1274..eae9057a91 100644 --- 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 _logBuffer = new ConcurrentQueue(); 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 currentBuffer = _logBuffer; + _logBuffer = new ConcurrentQueue(); + + // 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 index 6540bf229e..c381e631bf 100644 --- 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)")] [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)")] \ No newline at end of file +[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)")] +[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.")] \ No newline at end of file diff --git a/src/WebJobs.Script/Host/ScriptHost.cs b/src/WebJobs.Script/Host/ScriptHost.cs index 7f69ac12d0..fd1900812c 100644 --- 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 index 60aa08b3a1..20ef0151a3 100644 --- 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(); } } }