Skip to content

Commit 6f01933

Browse files
paulbatumpaulbatum
committed
More console log buffer improvements:
- Make a BufferedConsoleWriter type that is easier to reuse - Use IOptions and added test coverage for options setup - Seal the BufferedConsoleWriter to simplify IDisposable
1 parent 243d1fe commit 6f01933

File tree

7 files changed

+245
-86
lines changed

7 files changed

+245
-86
lines changed

‎src/WebJobs.Script.WebHost/Diagnostics/ConsoleWriter.cs‎ renamed to ‎src/WebJobs.Script.WebHost/Diagnostics/BufferedConsoleWriter.cs‎

Lines changed: 21 additions & 56 deletions
Original file line numberDiff line numberDiff line change
@@ -9,13 +9,8 @@
99

1010
namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
1111
{
12-
internal class ConsoleWriter : IDisposable
12+
internal sealed class BufferedConsoleWriter : IDisposable
1313
{
14-
// A typical out-of-proc function execution will generate 8 log lines.
15-
// A single core container can potentially get around 1K RPS at the higher end, and a typical log line is around 300 bytes
16-
// So in the extreme case, this is about 1 second of buffer and should be less than 3MB
17-
private const int DefaultBufferSize = 8000;
18-
1914
// Because we read the log lines in batches from the buffer and write them to the console in one go,
2015
// we can influence the latency distribution by controlling how much of the buffer we will process in one pass.
2116
// If we set this to 1, the P50 latency will be low, but the P99 latency will be high.
@@ -34,46 +29,22 @@ internal class ConsoleWriter : IDisposable
3429
private Action<string> _writeEvent;
3530
private bool _disposed;
3631

37-
public ConsoleWriter(IEnvironment environment, Action<Exception> unhandledExceptionHandler)
38-
: this(environment, unhandledExceptionHandler, consoleBufferTimeout: DefaultConsoleBufferTimeout, autoStart: true)
32+
public BufferedConsoleWriter(int bufferSize, Action<Exception> exceptionHandler)
33+
: this(bufferSize, exceptionHandler, consoleBufferTimeout: DefaultConsoleBufferTimeout, autoStart: true)
3934
{
4035
}
4136

42-
internal ConsoleWriter(IEnvironment environment, Action<Exception> exceptionHandler, TimeSpan consoleBufferTimeout, bool autoStart)
37+
internal BufferedConsoleWriter(int bufferSize, Action<Exception> exceptionHandler, TimeSpan consoleBufferTimeout, bool autoStart)
4338
{
44-
bool consoleEnabled = environment.GetEnvironmentVariable(EnvironmentSettingNames.ConsoleLoggingDisabled) != "1";
45-
46-
if (consoleEnabled)
47-
{
48-
int maxBufferSize = environment.GetEnvironmentVariable(EnvironmentSettingNames.ConsoleLoggingBufferSize) switch
49-
{
50-
var s when int.TryParse(s, out int i) && i >= 0 => i,
51-
var s when int.TryParse(s, out int i) && i < 0 => throw new ArgumentOutOfRangeException(nameof(EnvironmentSettingNames.ConsoleLoggingBufferSize), "Console buffer size cannot be negative"),
52-
_ => DefaultBufferSize,
53-
};
54-
55-
if (maxBufferSize == 0)
56-
{
57-
// buffer size was set to zero - disable it
58-
_writeEvent = Console.WriteLine;
59-
}
60-
else
61-
{
62-
_consoleBuffer = Channel.CreateBounded<string>(new BoundedChannelOptions(maxBufferSize) { SingleReader = true, SingleWriter = false });
63-
_writeEvent = WriteToConsoleBuffer;
64-
_consoleBufferTimeout = consoleBufferTimeout;
65-
_writeResetEvent = new ManualResetEvent(true);
66-
_maxLinesPerWrite = maxBufferSize / SingleWriteBufferDenominator;
39+
_consoleBuffer = Channel.CreateBounded<string>(new BoundedChannelOptions(bufferSize) { SingleReader = true, SingleWriter = false });
40+
_writeEvent = WriteToConsoleBuffer;
41+
_consoleBufferTimeout = consoleBufferTimeout;
42+
_writeResetEvent = new ManualResetEvent(true);
43+
_maxLinesPerWrite = bufferSize / SingleWriteBufferDenominator;
6744

68-
if (autoStart)
69-
{
70-
StartProcessingBuffer();
71-
}
72-
}
73-
}
74-
else
45+
if (autoStart)
7546
{
76-
_writeEvent = (string s) => { };
47+
StartProcessingBuffer();
7748
}
7849

7950
_exceptionhandler = exceptionHandler;
@@ -86,12 +57,14 @@ public void WriteHandler(string evt)
8657

8758
private void WriteToConsoleBuffer(string evt)
8859
{
89-
if (_consoleBuffer.Writer.TryWrite(evt) == false)
60+
if (!_consoleBuffer.Writer.TryWrite(evt))
9061
{
9162
_writeResetEvent.Reset();
92-
if (_writeResetEvent.WaitOne(_consoleBufferTimeout) == false || _consoleBuffer.Writer.TryWrite(evt) == false)
63+
bool waitFailed = !_writeResetEvent.WaitOne(_consoleBufferTimeout);
64+
65+
// If the wait failed, write to the console. Otherwise, try the writing again - if that fails, write to the console.
66+
if (waitFailed || !_consoleBuffer.Writer.TryWrite(evt))
9367
{
94-
// We have either timed out or the buffer was full again, so just write directly to console
9568
Console.WriteLine(evt);
9669
}
9770
}
@@ -157,28 +130,20 @@ private async Task ProcessConsoleBufferAsync()
157130
}
158131
}
159132

160-
protected virtual void Dispose(bool disposing)
133+
public void Dispose()
161134
{
162135
if (!_disposed)
163136
{
164-
if (disposing)
137+
if (_consoleBuffer != null)
165138
{
166-
if (_consoleBuffer != null)
167-
{
168-
_consoleBuffer.Writer.TryComplete();
169-
_consoleBufferReadLoop.Wait(DisposeTimeout);
170-
}
171-
172-
_writeResetEvent?.Dispose();
139+
_consoleBuffer.Writer.TryComplete();
140+
_consoleBufferReadLoop.Wait(DisposeTimeout);
173141
}
174142

143+
_writeResetEvent?.Dispose();
175144
_disposed = true;
176145
}
177-
}
178146

179-
public void Dispose()
180-
{
181-
Dispose(disposing: true);
182147
GC.SuppressFinalize(this);
183148
}
184149
}

‎src/WebJobs.Script.WebHost/Diagnostics/LinuxContainerEventGenerator.cs‎

Lines changed: 26 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -2,7 +2,9 @@
22
// Licensed under the MIT License. See License.txt in the project root for license information.
33

44
using System;
5+
using Microsoft.Azure.WebJobs.Script.Config;
56
using Microsoft.Extensions.Logging;
7+
using Microsoft.Extensions.Options;
68

79
namespace Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics
810
{
@@ -11,19 +13,38 @@ internal class LinuxContainerEventGenerator : LinuxEventGenerator, IDisposable
1113
private const int MaxDetailsLength = 10000;
1214
private static readonly Lazy<LinuxContainerEventGenerator> _Lazy = new Lazy<LinuxContainerEventGenerator>(() => new LinuxContainerEventGenerator(SystemEnvironment.Instance, Console.WriteLine));
1315
private readonly Action<string> _writeEvent;
14-
private readonly ConsoleWriter _consoleWriter;
16+
private readonly BufferedConsoleWriter _consoleWriter;
1517
private readonly IEnvironment _environment;
1618
private string _containerName;
1719
private string _stampName;
1820
private string _tenantId;
1921
private bool _disposed;
2022

21-
public LinuxContainerEventGenerator(IEnvironment environment, Action<string> writeEvent = null)
23+
public LinuxContainerEventGenerator(IEnvironment environment, IOptions<ConsoleLoggingOptions> consoleLoggingOptions)
24+
{
25+
if (consoleLoggingOptions.Value.LoggingDisabled)
26+
{
27+
_writeEvent = (string s) => { };
28+
}
29+
else if (!consoleLoggingOptions.Value.BufferEnabled)
30+
{
31+
_writeEvent = Console.WriteLine;
32+
}
33+
else
34+
{
35+
_consoleWriter = new BufferedConsoleWriter(consoleLoggingOptions.Value.BufferSize, LogUnhandledException);
36+
_writeEvent = _consoleWriter.WriteHandler;
37+
}
38+
39+
_environment = environment;
40+
_containerName = _environment.GetEnvironmentVariable(EnvironmentSettingNames.ContainerName)?.ToUpperInvariant();
41+
}
42+
43+
public LinuxContainerEventGenerator(IEnvironment environment, Action<string> writeEvent)
2244
{
2345
if (writeEvent == null)
2446
{
25-
_consoleWriter = new ConsoleWriter(environment, LogUnhandledException);
26-
writeEvent = _consoleWriter.WriteHandler;
47+
throw new ArgumentNullException(nameof(writeEvent));
2748
}
2849

2950
_writeEvent = writeEvent;
@@ -33,7 +54,7 @@ public LinuxContainerEventGenerator(IEnvironment environment, Action<string> wri
3354
}
3455

3556
// For testing
36-
internal LinuxContainerEventGenerator(IEnvironment environment, ConsoleWriter consoleWriter)
57+
internal LinuxContainerEventGenerator(IEnvironment environment, BufferedConsoleWriter consoleWriter)
3758
{
3859
_environment = environment;
3960
_consoleWriter = consoleWriter;

‎src/WebJobs.Script.WebHost/WebHostServiceCollectionExtensions.cs‎

Lines changed: 4 additions & 7 deletions
Original file line numberDiff line numberDiff line change
@@ -99,14 +99,10 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
9999
services.AddSingleton<IEventGenerator>(p =>
100100
{
101101
var environment = p.GetService<IEnvironment>();
102-
if (environment.IsLinuxConsumptionOnAtlas())
103-
{
104-
return new LinuxContainerEventGenerator(environment);
105-
}
106-
else if (environment.IsLinuxConsumptionOnLegion())
102+
if (environment.IsAnyLinuxConsumption())
107103
{
108-
//todo: Replace with legion specific logger
109-
return new LinuxContainerEventGenerator(environment);
104+
var consoleLoggingOptions = p.GetService<IOptions<ConsoleLoggingOptions>>();
105+
return new LinuxContainerEventGenerator(environment, consoleLoggingOptions);
110106
}
111107
else if (SystemEnvironment.Instance.IsLinuxAppService())
112108
{
@@ -207,6 +203,7 @@ public static void AddWebJobsScriptHost(this IServiceCollection services, IConfi
207203
services.ConfigureOptionsWithChangeTokenSource<LanguageWorkerOptions, LanguageWorkerOptionsSetup, SpecializationChangeTokenSource<LanguageWorkerOptions>>();
208204
services.ConfigureOptionsWithChangeTokenSource<AppServiceOptions, AppServiceOptionsSetup, SpecializationChangeTokenSource<AppServiceOptions>>();
209205
services.ConfigureOptionsWithChangeTokenSource<HttpBodyControlOptions, HttpBodyControlOptionsSetup, SpecializationChangeTokenSource<HttpBodyControlOptions>>();
206+
services.ConfigureOptions<ConsoleLoggingOptionsSetup>();
210207
services.ConfigureOptions<FunctionsHostingConfigOptionsSetup>();
211208
if (configuration != null)
212209
{

‎src/WebJobs.Script/Config/ConsoleLoggingOptions.cs‎

Lines changed: 26 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,26 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
namespace Microsoft.Azure.WebJobs.Script.Config
5+
{
6+
public class ConsoleLoggingOptions
7+
{
8+
// A typical out-of-proc function execution will generate 8 log lines.
9+
// A single core container can potentially get around 1K RPS at the higher end, and a typical log line is around 300 bytes
10+
// So in the extreme case, this is about 1 second of buffer and should be less than 3MB
11+
public const int DefaultBufferSize = 8000;
12+
13+
public ConsoleLoggingOptions()
14+
{
15+
LoggingDisabled = false;
16+
BufferEnabled = true;
17+
BufferSize = DefaultBufferSize;
18+
}
19+
20+
public bool LoggingDisabled { get; set; }
21+
22+
public bool BufferEnabled { get; set; }
23+
24+
public int BufferSize { get; set; }
25+
}
26+
}

‎src/WebJobs.Script/Config/ConsoleLoggingOptionsSetup.cs‎

Lines changed: 33 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,33 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System;
5+
using Microsoft.Extensions.Configuration;
6+
using Microsoft.Extensions.Options;
7+
8+
namespace Microsoft.Azure.WebJobs.Script.Config
9+
{
10+
public class ConsoleLoggingOptionsSetup : IConfigureOptions<ConsoleLoggingOptions>
11+
{
12+
private readonly IConfiguration _configuration;
13+
14+
public ConsoleLoggingOptionsSetup(IConfiguration configuration)
15+
{
16+
_configuration = configuration;
17+
}
18+
19+
public void Configure(ConsoleLoggingOptions options)
20+
{
21+
options.LoggingDisabled = _configuration.GetValue<int>(EnvironmentSettingNames.ConsoleLoggingDisabled) == 1;
22+
23+
int bufferSize = _configuration.GetValue<int>(EnvironmentSettingNames.ConsoleLoggingBufferSize, ConsoleLoggingOptions.DefaultBufferSize);
24+
if (bufferSize < 0)
25+
{
26+
throw new ArgumentOutOfRangeException(nameof(EnvironmentSettingNames.ConsoleLoggingBufferSize), "Console buffer size cannot be negative");
27+
}
28+
29+
options.BufferEnabled = bufferSize > 0;
30+
options.BufferSize = bufferSize;
31+
}
32+
}
33+
}

‎test/WebJobs.Script.Tests/Configuration/ConsoleLoggingOptionsSetupTests.cs‎

Lines changed: 92 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,92 @@
1+
// Copyright (c) .NET Foundation. All rights reserved.
2+
// Licensed under the MIT License. See License.txt in the project root for license information.
3+
4+
using System.Collections.Generic;
5+
using Microsoft.Azure.WebJobs.Script.Config;
6+
using Microsoft.Extensions.Configuration;
7+
using Xunit;
8+
9+
namespace Microsoft.Azure.WebJobs.Script.Tests.Configuration
10+
{
11+
public class ConsoleLoggingOptionsSetupTests
12+
{
13+
[Fact]
14+
public void ConsoleLoggingOptionsSetup_ConfiguresExpectedDefaults()
15+
{
16+
IConfiguration config = new ConfigurationBuilder()
17+
.AddInMemoryCollection(new Dictionary<string, string>
18+
{
19+
//{ $"{SamplingSettings}:MaxTelemetryItemsPerSecond", "25" },
20+
//{ $"{SamplingSettings}:IsEnabled", "false" }
21+
})
22+
.Build();
23+
24+
ConsoleLoggingOptionsSetup setup = new ConsoleLoggingOptionsSetup(config);
25+
ConsoleLoggingOptions options = new ConsoleLoggingOptions();
26+
27+
setup.Configure(options);
28+
29+
Assert.Equal(true, options.BufferEnabled);
30+
Assert.Equal(false, options.LoggingDisabled);
31+
Assert.Equal(8000, options.BufferSize);
32+
}
33+
34+
[Theory]
35+
[InlineData("1", true)]
36+
[InlineData("0", false)]
37+
[InlineData(null, false)]
38+
public void ConsoleLoggingOptionsSetup_CanDisableLogging(string value, bool expectLoggingDisabled)
39+
{
40+
var settings = new Dictionary<string, string>();
41+
42+
if (value != null)
43+
{
44+
settings[EnvironmentSettingNames.ConsoleLoggingDisabled] = value;
45+
}
46+
47+
IConfiguration config = new ConfigurationBuilder()
48+
.AddInMemoryCollection(settings)
49+
.Build();
50+
51+
ConsoleLoggingOptionsSetup setup = new ConsoleLoggingOptionsSetup(config);
52+
ConsoleLoggingOptions options = new ConsoleLoggingOptions();
53+
setup.Configure(options);
54+
55+
Assert.Equal(expectLoggingDisabled, options.LoggingDisabled);
56+
}
57+
58+
[Fact]
59+
public void ConsoleLoggingOptionsSetup_CanDisableBuffer()
60+
{
61+
var settings = new Dictionary<string, string>();
62+
settings[EnvironmentSettingNames.ConsoleLoggingBufferSize] = "0";
63+
64+
IConfiguration config = new ConfigurationBuilder()
65+
.AddInMemoryCollection(settings)
66+
.Build();
67+
68+
ConsoleLoggingOptionsSetup setup = new ConsoleLoggingOptionsSetup(config);
69+
ConsoleLoggingOptions options = new ConsoleLoggingOptions();
70+
setup.Configure(options);
71+
72+
Assert.Equal(false, options.BufferEnabled);
73+
}
74+
75+
[Fact]
76+
public void ConsoleLoggingOptionsSetup_CanSetBufferSize()
77+
{
78+
var settings = new Dictionary<string, string>();
79+
settings[EnvironmentSettingNames.ConsoleLoggingBufferSize] = "100";
80+
81+
IConfiguration config = new ConfigurationBuilder()
82+
.AddInMemoryCollection(settings)
83+
.Build();
84+
85+
ConsoleLoggingOptionsSetup setup = new ConsoleLoggingOptionsSetup(config);
86+
ConsoleLoggingOptions options = new ConsoleLoggingOptions();
87+
setup.Configure(options);
88+
89+
Assert.Equal(100, options.BufferSize);
90+
}
91+
}
92+
}

0 commit comments

Comments
 (0)