Skip to content

Commit fc5a4cf

Browse files
mathewcmathewc
committed
ColdStart request logging
1 parent 74d5cc7 commit fc5a4cf

File tree

7 files changed

+63
-5
lines changed

7 files changed

+63
-5
lines changed

‎src/WebJobs.Script.WebHost/Handlers/SystemTraceHandler.cs‎

Lines changed: 11 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -39,6 +39,17 @@ private TraceWriter TraceWriter
3939

4040
protected override async Task<HttpResponseMessage> SendAsync(HttpRequestMessage request, CancellationToken cancellationToken)
4141
{
42+
if (request.IsColdStart())
43+
{
44+
// for cold start requests we want to measure the request
45+
// pipeline dispatch time
46+
// important that this stopwatch is started as early as possible
47+
// in the pipeline (in this case, in our first handler)
48+
var sw = new Stopwatch();
49+
sw.Start();
50+
request.Properties.Add(ScriptConstants.AzureFunctionsColdStartKey, sw);
51+
}
52+
4253
var details = new JObject
4354
{
4455
{ "requestId", request.GetRequestId() },

‎src/WebJobs.Script.WebHost/Handlers/WebScriptHostHandler.cs‎

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

44
using System;
5+
using System.Diagnostics;
56
using System.Net.Http;
67
using System.Threading;
78
using System.Threading.Tasks;

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

Lines changed: 38 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -28,6 +28,8 @@
2828
using Microsoft.Azure.WebJobs.Script.WebHost.Diagnostics;
2929
using Microsoft.Azure.WebJobs.Script.WebHost.Extensions;
3030
using Microsoft.Extensions.Logging;
31+
using Newtonsoft.Json;
32+
using Newtonsoft.Json.Linq;
3133

3234
namespace Microsoft.Azure.WebJobs.Script.WebHost
3335
{
@@ -38,6 +40,7 @@ public class WebScriptHostManager : ScriptHostManager
3840
private readonly WebHostMetricsLogger _metricsLogger;
3941
private readonly ISecretManager _secretManager;
4042
private readonly WebHostSettings _webHostSettings;
43+
private readonly ScriptSettingsManager _settingsManager;
4144
private readonly IWebJobsExceptionHandler _exceptionHandler;
4245
private readonly ScriptHostConfiguration _config;
4346
private readonly ISwaggerDocumentManager _swaggerDocumentManager;
@@ -49,6 +52,7 @@ public class WebScriptHostManager : ScriptHostManager
4952
private bool _hostStarted = false;
5053
private HttpRouteCollection _httpRoutes;
5154
private HttpRequestManager _httpRequestManager;
55+
private SystemTraceWriter _systemTraceWriter;
5256

5357
public WebScriptHostManager(ScriptHostConfiguration config,
5458
ISecretManagerFactory secretManagerFactory,
@@ -66,18 +70,19 @@ public WebScriptHostManager(ScriptHostConfiguration config,
6670
_metricsLogger = new WebHostMetricsLogger();
6771
_exceptionHandler = new WebScriptHostExceptionHandler(this);
6872
_webHostSettings = webHostSettings;
73+
_settingsManager = settingsManager;
6974
_hostTimeoutSeconds = hostTimeoutSeconds;
7075
_hostRunningPollIntervalMilliseconds = hostPollingIntervalMilliseconds;
7176

7277
var systemEventGenerator = config.HostConfig.GetService<IEventGenerator>() ?? new EventGenerator();
73-
var systemTraceWriter = new SystemTraceWriter(systemEventGenerator, settingsManager, TraceLevel.Verbose);
78+
_systemTraceWriter = new SystemTraceWriter(systemEventGenerator, settingsManager, TraceLevel.Verbose);
7479
if (config.TraceWriter != null)
7580
{
76-
config.TraceWriter = new CompositeTraceWriter(new TraceWriter[] { config.TraceWriter, systemTraceWriter });
81+
config.TraceWriter = new CompositeTraceWriter(new TraceWriter[] { config.TraceWriter, _systemTraceWriter });
7782
}
7883
else
7984
{
80-
config.TraceWriter = systemTraceWriter;
85+
config.TraceWriter = _systemTraceWriter;
8186
}
8287

8388
config.IsSelfHost = webHostSettings.IsSelfHost;
@@ -169,7 +174,37 @@ public async Task<HttpResponseMessage> HandleRequestAsync(FunctionDescriptor fun
169174
};
170175
using (logger.BeginScope(scopeState))
171176
{
177+
JObject coldStartData = null;
178+
if (request.IsColdStart())
179+
{
180+
coldStartData = new JObject
181+
{
182+
{ "requestId", request.GetRequestId() },
183+
{ "language", function.Metadata.ScriptType.ToString() },
184+
{ "sku", _settingsManager.WebsiteSku }
185+
};
186+
187+
var dispatchStopwatch = request.GetPropertyOrDefault<Stopwatch>(ScriptConstants.AzureFunctionsColdStartKey);
188+
if (dispatchStopwatch != null)
189+
{
190+
dispatchStopwatch.Stop();
191+
coldStartData.Add("dispatchDuration", dispatchStopwatch.ElapsedMilliseconds);
192+
}
193+
}
194+
195+
var functionStopwatch = new Stopwatch();
196+
functionStopwatch.Start();
172197
await Instance.CallAsync(function.Name, arguments, cancellationToken);
198+
functionStopwatch.Stop();
199+
200+
if (coldStartData != null)
201+
{
202+
coldStartData.Add("functionDuration", functionStopwatch.ElapsedMilliseconds);
203+
204+
var coldStartEvent = new TraceEvent(TraceLevel.Info, coldStartData.ToString(Formatting.None));
205+
coldStartEvent.Properties.Add(ScriptConstants.TracePropertyEventNameKey, ScriptConstants.ColdStartEventName);
206+
_systemTraceWriter.Trace(coldStartEvent);
207+
}
173208
}
174209
}
175210

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

Lines changed: 3 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -28,7 +28,9 @@ public static ScriptSettingsManager Instance
2828

2929
public virtual bool IsZipDeployment => !string.IsNullOrEmpty(GetSetting(EnvironmentSettingNames.AzureWebsiteZipDeployment));
3030

31-
public bool IsDynamicSku => GetSetting(EnvironmentSettingNames.AzureWebsiteSku) == ScriptConstants.DynamicSku;
31+
public string WebsiteSku => GetSetting(EnvironmentSettingNames.AzureWebsiteSku);
32+
33+
public bool IsDynamicSku => WebsiteSku == ScriptConstants.DynamicSku;
3234

3335
public virtual string AzureWebsiteDefaultSubdomain
3436
{

‎src/WebJobs.Script/Extensions/HttpRequestMessageExtensions.cs‎

Lines changed: 5 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -42,6 +42,11 @@ public static T GetPropertyOrDefault<T>(this HttpRequestMessage request, string
4242
return request.GetRequestPropertyOrDefault<T>(propertyName);
4343
}
4444

45+
public static bool IsColdStart(this HttpRequestMessage request)
46+
{
47+
return !string.IsNullOrEmpty(request.GetHeaderValueOrDefault(ScriptConstants.AntaresColdStartHeaderName));
48+
}
49+
4550
public static bool IsAntaresInternalRequest(this HttpRequestMessage request)
4651
{
4752
if (!ScriptSettingsManager.Instance.IsAzureEnvironment)

‎src/WebJobs.Script/GlobalSuppressions.cs‎

Lines changed: 2 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -239,4 +239,5 @@
239239
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1709:IdentifiersShouldBeCasedCorrectly", MessageId = "Io", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Scale.ApplicationPerformanceCounters.#OtherIoBytes")]
240240
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Reliability", "CA2000:Dispose objects before losing scope", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#.ctor(Microsoft.Azure.WebJobs.Script.ScriptHostConfiguration,Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager,Microsoft.Azure.WebJobs.Script.IScriptHostFactory,Microsoft.Azure.WebJobs.Script.Eventing.IScriptEventManager,Microsoft.Azure.WebJobs.Script.IScriptHostEnvironment,Microsoft.Azure.WebJobs.Script.Scale.HostPerformanceManager)")]
241241
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Usage", "CA2213:DisposableFieldsShouldBeDisposed", MessageId = "_hostHealthCheckTimer", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#Dispose(System.Boolean)")]
242-
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Maintainability", "CA1502:AvoidExcessiveComplexity", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#RunAndBlock(System.Threading.CancellationToken)")]
242+
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Maintainability", "CA1502:AvoidExcessiveComplexity", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.ScriptHostManager.#RunAndBlock(System.Threading.CancellationToken)")]
243+
[assembly: System.Diagnostics.CodeAnalysis.SuppressMessage("Microsoft.Naming", "CA1704:IdentifiersShouldBeSpelledCorrectly", MessageId = "Sku", Scope = "member", Target = "Microsoft.Azure.WebJobs.Script.Config.ScriptSettingsManager.#WebsiteSku")]

‎src/WebJobs.Script/ScriptConstants.cs‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -14,6 +14,7 @@ public static class ScriptConstants
1414
public const string AzureFunctionsHttpRequestAuthorizationDisabledKey = "MS_AzureFunctionsAuthorizationDisabled";
1515
public const string AzureFunctionsHttpFunctionKey = "MS_AzureFunctionsHttpFunction";
1616
public const string AzureFunctionsRequestIdKey = "MS_AzureFunctionsRequestID";
17+
public const string AzureFunctionsColdStartKey = "MS_AzureFunctionsColdStart";
1718
public const string AzureFunctionsHttpRequestKey = "MS_AzureFunctionsHttpRequest";
1819
public const string AzureProxyFunctionExecutorKey = "MS_AzureProxyFunctionExecutor";
1920

@@ -54,9 +55,11 @@ public static class ScriptConstants
5455
public const string ProxyMetadataFileName = "proxies.json";
5556
public const string DefaultMasterKeyName = "master";
5657
public const string DefaultFunctionKeyName = "default";
58+
public const string ColdStartEventName = "ColdStart";
5759

5860
public const string AntaresLogIdHeaderName = "X-ARR-LOG-ID";
5961
public const string AntaresScaleOutHeaderName = "X-FUNCTION-SCALEOUT";
62+
public const string AntaresColdStartHeaderName = "X-MS-COLDSTART";
6063
public const string DynamicSku = "Dynamic";
6164
public const string DefaultProductionSlotName = "production";
6265

0 commit comments

Comments
 (0)