Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Performance Improvements - Logging #2946

Merged
merged 19 commits into from
Apr 4, 2023
Merged

Performance Improvements - Logging #2946

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
19 commits
Select commit Hold shift + click to select a range
76b86d7
Initial Commit.
RohitRanjanMS Jan 9, 2023
7d4e4d1
Fixed Eventid
RohitRanjanMS Jan 18, 2023
0932332
More changes
RohitRanjanMS Jan 20, 2023
b8f46a0
More changes
RohitRanjanMS Jan 23, 2023
963f0bb
Fixed current scope
RohitRanjanMS Jan 24, 2023
16f4026
Update src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/Applic…
RohitRanjanMS Jan 25, 2023
7ff0886
Fixed if else
RohitRanjanMS Jan 26, 2023
7b42189
Merge branch 'roranjan/AILoggerPerfImprovement' of https://github.com…
RohitRanjanMS Jan 26, 2023
a771b61
Removed state from DictionaryScope
RohitRanjanMS Feb 3, 2023
26595a5
Pattern matching
RohitRanjanMS Feb 10, 2023
3818c14
Removed space
RohitRanjanMS Feb 10, 2023
923a3c8
Removed unused namespace
RohitRanjanMS Feb 14, 2023
66eba1d
Fixed null handling.
RohitRanjanMS Mar 15, 2023
a53f39d
Optimizing for the first `BeginScope` invocation.
RohitRanjanMS Mar 21, 2023
c8d909c
Fixed code
RohitRanjanMS Mar 21, 2023
97eb097
Added tests to validate overriding in DictionaryLoggerScope.
RohitRanjanMS Mar 28, 2023
b83c6a3
Fixed int/double casting.
RohitRanjanMS Mar 29, 2023
591395b
Add scope properties for logs emitted using TelemetryClient.
RohitRanjanMS Apr 4, 2023
550d8fe
Fixed spacing
RohitRanjanMS Apr 4, 2023
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
215 changes: 119 additions & 96 deletions src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -9,9 +9,11 @@
using System.Linq;
using System.Text;
using Microsoft.ApplicationInsights;
using Microsoft.ApplicationInsights.Channel;
using Microsoft.ApplicationInsights.DataContracts;
using Microsoft.ApplicationInsights.Extensibility;
using Microsoft.AspNetCore.Http;
using Microsoft.Azure.WebJobs.Logging.ApplicationInsights.Extensions;
using Microsoft.Extensions.Logging;
using Microsoft.Extensions.Primitives;

Expand Down Expand Up @@ -73,50 +75,41 @@ public void Log<TState>(LogLevel logLevel, EventId eventId, TState state,
// Initialize stateValues so the rest of the methods don't have to worry about null values.
stateValues = stateValues ?? new Dictionary<string, object>();

// Add some well-known properties to the scope dictionary so the TelemetryInitializer can add them
// for all telemetry.
using (BeginScope(new Dictionary<string, object>
if (_isUserFunction && eventId.Id == LogConstants.MetricEventId)
{
[LogConstants.CategoryNameKey] = _categoryName,
[LogConstants.LogLevelKey] = (LogLevel?)logLevel,
[LogConstants.EventIdKey] = eventId.Id,
[LogConstants.EventNameKey] = eventId.Name,
}))
// Log a metric from user logs only
LogMetric(stateValues, logLevel, eventId);
}
else if (_categoryName == LogCategories.Results)
{
if (_isUserFunction && eventId.Id == LogConstants.MetricEventId)
{
// Log a metric from user logs only
LogMetric(stateValues);
}
else if (_categoryName == LogCategories.Results)
{
// Log a function result
LogFunctionResult(stateValues, logLevel, exception);
}
else if (_categoryName == LogCategories.Aggregator)
{
// Log an aggregate record
LogFunctionResultAggregate(stateValues);
}
else if (exception != null)
{
// Log an exception
LogException(logLevel, stateValues, exception, formattedMessage);
}
else
{
// Otherwise, log a trace
LogTrace(logLevel, stateValues, formattedMessage);
}
// Log a function result
LogFunctionResult(stateValues, logLevel, exception, eventId);
}
else if (_categoryName == LogCategories.Aggregator)
{
// Log an aggregate record
LogFunctionResultAggregate(stateValues, logLevel, eventId);
}
else if (exception != null)
{
// Log an exception
LogException(logLevel, stateValues, exception, formattedMessage, eventId);
}
else
{
// Otherwise, log a trace
LogTrace(logLevel, stateValues, formattedMessage, eventId);
}
}

private void LogMetric(IEnumerable<KeyValuePair<string, object>> values)
private void LogMetric(IEnumerable<KeyValuePair<string, object>> values, LogLevel logLevel, EventId eventId)
{
MetricTelemetry telemetry = new MetricTelemetry();

// Always apply scope first to allow state to override.
ApplyScopeProperties(telemetry.Properties);
ApplyScopeProperties(telemetry);

// Add known properties like category, logLevel and event
ApplyKnownProperties(telemetry.Properties, logLevel, eventId);

foreach (var entry in values)
{
Expand All @@ -129,11 +122,11 @@ private void LogMetric(IEnumerable<KeyValuePair<string, object>> values)
// next entry if found.
switch (entry.Key)
{
case LogConstants.NameKey:
telemetry.Name = entry.Value.ToString();
case LogConstants.NameKey when entry.Value is string name:
telemetry.Name = name;
continue;
case LogConstants.MetricValueKey:
telemetry.Sum = (double)entry.Value;
case LogConstants.MetricValueKey when entry.Value is double sum:
telemetry.Sum = sum;
continue;
default:
break;
Expand All @@ -142,8 +135,8 @@ private void LogMetric(IEnumerable<KeyValuePair<string, object>> values)
// Now check for case-insensitive matches
switch (entry.Key.ToLowerInvariant())
{
case MetricCountKey:
telemetry.Count = Convert.ToInt32(entry.Value);
case MetricCountKey when entry.Value is int count:
telemetry.Count = count;
break;
case MetricMinKey:
telemetry.Min = Convert.ToDouble(entry.Value);
Expand All @@ -165,17 +158,28 @@ private void LogMetric(IEnumerable<KeyValuePair<string, object>> values)
}

// Applies scope properties; filters most system properties, which are used internally
private static void ApplyScopeProperties(IDictionary<string, string> properties)
private static void ApplyScopeProperties(ITelemetry telemetry)
{
var scopeProperties = DictionaryLoggerScope.GetMergedStateDictionaryOrNull();
if (scopeProperties != null)
{
var customScopeProperties = scopeProperties.Where(p => !SystemScopeKeys.Contains(p.Key, StringComparer.Ordinal));
ApplyProperties(properties, customScopeProperties, true);
}
foreach (var scopeProperty in scopeProperties)
{
if (scopeProperty.Value != null && !SystemScopeKeys.Contains(scopeProperty.Key, StringComparer.Ordinal))
{
ApplyProperty(telemetry.Context.Properties, scopeProperty.Key, scopeProperty.Value, true);
}
}

if (scopeProperties.GetValueOrDefault<string>(ScopeKeys.FunctionInvocationId) is string invocationId)
{
telemetry.Context.Properties[LogConstants.InvocationIdKey] = invocationId;
}
}
telemetry.Context.Operation.Name = scopeProperties.GetValueOrDefault<string>(ScopeKeys.FunctionName);
}

private void LogException(LogLevel logLevel, IEnumerable<KeyValuePair<string, object>> values, Exception exception, string formattedMessage)
private void LogException(LogLevel logLevel, IEnumerable<KeyValuePair<string, object>> values, Exception exception, string formattedMessage, EventId eventId)
{
ExceptionTelemetry telemetry = new ExceptionTelemetry(exception)
{
Expand All @@ -189,29 +193,33 @@ private void LogException(LogLevel logLevel, IEnumerable<KeyValuePair<string, ob

// Also log a trace if there's a formattedMessage. This ensures that the error is visible
// in both App Insights analytics tables.
LogTrace(logLevel, values, formattedMessage);
LogTrace(logLevel, values, formattedMessage, eventId);
}

ApplyScopeAndStateProperties(telemetry.Properties, values);
ApplyScopeAndStateProperties(telemetry.Properties, values, telemetry);
ApplyKnownProperties(telemetry.Properties, logLevel, eventId);

_telemetryClient.TrackException(telemetry);
}

private void LogTrace(LogLevel logLevel, IEnumerable<KeyValuePair<string, object>> values, string formattedMessage)
private void LogTrace(LogLevel logLevel, IEnumerable<KeyValuePair<string, object>> values, string formattedMessage, EventId eventId)
{
var properties = new Dictionary<string, string>();
ApplyScopeAndStateProperties(properties, values);
TraceTelemetry telemetry = new TraceTelemetry(formattedMessage);

ApplyScopeAndStateProperties(telemetry.Properties, values, telemetry);

ApplyKnownProperties(telemetry.Properties, logLevel, eventId);

var severityLevel = GetSeverityLevel(logLevel);


if (severityLevel.HasValue)
{
_telemetryClient.TrackTrace(formattedMessage, severityLevel.Value, properties);
}
else
{
// LogLevel.None maps to null, so we have to handle that specially
_telemetryClient.TrackTrace(formattedMessage, properties);
telemetry.SeverityLevel = severityLevel;
}

// LogLevel.None maps to null, so we have to handle that specially
_telemetryClient.TrackTrace(telemetry);
}

private static SeverityLevel? GetSeverityLevel(LogLevel logLevel)
Expand All @@ -236,35 +244,52 @@ private void LogTrace(LogLevel logLevel, IEnumerable<KeyValuePair<string, object
}

// Makes sure these are done in the correct order. If there are duplicate keys, the last State property wins.
private static void ApplyScopeAndStateProperties(IDictionary<string, string> properties, IEnumerable<KeyValuePair<string, object>> state)
private static void ApplyScopeAndStateProperties(IDictionary<string, string> properties, IEnumerable<KeyValuePair<string, object>> state, ITelemetry telemetry)
{
ApplyScopeProperties(properties);
ApplyScopeProperties(telemetry);
ApplyProperties(properties, state, true);
}

internal static void ApplyProperty(IDictionary<string, string> properties, string key, object value, bool applyPrefix = false)
internal void ApplyKnownProperties(IDictionary<string, string> properties, LogLevel logLevel, EventId eventId)
{
properties[LogConstants.CategoryNameKey] = _categoryName;
properties[LogConstants.LogLevelKey] = logLevel.ToStringOptimized();

if (eventId.Id != 0)
{
properties[LogConstants.EventIdKey] = Convert.ToString(eventId.Id);
}
if (!string.IsNullOrEmpty(eventId.Name))
{
properties[LogConstants.EventNameKey] = eventId.Name;
}
}
internal static void ApplyProperty(IDictionary<string, string> properties, string key, object objectValue, bool applyPrefix = false)
{
// do not apply null values
if (value == null)
if (objectValue == null)
{
return;
}

string stringValue = null;

// Format dates
Type propertyType = value.GetType();
if (propertyType == typeof(DateTime))
if (objectValue is string value)
{
stringValue = ((DateTime)value).ToUniversalTime().ToString(DateTimeFormatString);
stringValue = value;
}
else if (propertyType == typeof(DateTimeOffset))
else if (objectValue is DateTime date)
{
stringValue = ((DateTimeOffset)value).UtcDateTime.ToString(DateTimeFormatString);
stringValue = date.ToUniversalTime().ToString(DateTimeFormatString);
}
else if (objectValue is DateTimeOffset dateOffset)
{
stringValue = dateOffset.UtcDateTime.ToString(DateTimeFormatString);
}
else
{
stringValue = value.ToString();
stringValue = objectValue.ToString();
}

string prefixedKey = applyPrefix ? _prefixedProperyNames.GetOrAdd(key, k =>
Expand All @@ -288,59 +313,65 @@ private static void ApplyProperties(IDictionary<string, string> properties, IEnu
}
}

private void LogFunctionResultAggregate(IEnumerable<KeyValuePair<string, object>> values)
private void LogFunctionResultAggregate(IEnumerable<KeyValuePair<string, object>> values, LogLevel logLevel, EventId eventId)
{
// Metric names will be created like "{FunctionName} {MetricName}"
IDictionary<string, double> metrics = new Dictionary<string, double>();
IDictionary<string, double> metrics = new Dictionary<string, double>(7);
string functionName = LoggingConstants.Unknown;

// build up the collection of metrics to send
foreach (KeyValuePair<string, object> value in values)
{
switch (value.Key)
{
case LogConstants.NameKey:
functionName = value.Value.ToString();
case LogConstants.NameKey when value.Value is string name:
functionName = name;
break;
case LogConstants.TimestampKey:
case LogConstants.OriginalFormatKey:
// Timestamp is created automatically
// We won't use the format string here
break;
default:
if (value.Value is TimeSpan)
if (value.Value is int intValue)
{
// if it's a TimeSpan, log the milliseconds
metrics.Add(value.Key, ((TimeSpan)value.Value).TotalMilliseconds);
metrics.Add(value.Key, Convert.ToDouble(intValue));
}
else if (value.Value is double || value.Value is int)
else if (value.Value is double doubleValue)
{
metrics.Add(value.Key, Convert.ToDouble(value.Value));
metrics.Add(value.Key, doubleValue);
}
else if (value.Value is TimeSpan timeSpan)
{
// if it's a TimeSpan, log the milliseconds
metrics.Add(value.Key, timeSpan.TotalMilliseconds);
}

// do nothing otherwise
break;
}
}

IDictionary<string, string> properties = new Dictionary<string, string>(2);
ApplyKnownProperties(properties, logLevel, eventId);

foreach (KeyValuePair<string, double> metric in metrics)
{
_telemetryClient.TrackMetric($"{functionName} {metric.Key}", metric.Value);
_telemetryClient.TrackMetric($"{functionName} {metric.Key}", metric.Value, properties);
RohitRanjanMS marked this conversation as resolved.
Show resolved Hide resolved
}
}

private void LogFunctionResult(IEnumerable<KeyValuePair<string, object>> state, LogLevel logLevel, Exception exception)
private void LogFunctionResult(IEnumerable<KeyValuePair<string, object>> state, LogLevel logLevel, Exception exception, EventId eventId)
{
IDictionary<string, object> scopeProps = DictionaryLoggerScope.GetMergedStateDictionaryOrNull();
IReadOnlyDictionary<string, object> scopeProps = DictionaryLoggerScope.GetMergedStateDictionaryOrNull();
KeyValuePair<string, object>[] stateProps = state as KeyValuePair<string, object>[] ?? state.ToArray();

// log associated exception details
if (exception != null)
{
LogException(logLevel, stateProps, exception, null);
LogException(logLevel, stateProps, exception, null, eventId);
}

ApplyFunctionResultActivityTags(stateProps, scopeProps);
ApplyFunctionResultActivityTags(stateProps, scopeProps, logLevel);

IOperationHolder<RequestTelemetry> requestOperation = scopeProps?.GetValueOrDefault<IOperationHolder<RequestTelemetry>>(OperationContext);
if (requestOperation != null)
Expand All @@ -362,7 +393,7 @@ private void LogFunctionResult(IEnumerable<KeyValuePair<string, object>> state,
/// </summary>
/// <param name="state"></param>
/// <param name="scope"></param>
private void ApplyFunctionResultActivityTags(IEnumerable<KeyValuePair<string, object>> state, IDictionary<string, object> scope)
private void ApplyFunctionResultActivityTags(IEnumerable<KeyValuePair<string, object>> state, IReadOnlyDictionary<string, object> scope, LogLevel logLevel)
{
// Activity carries tracing context. It is managed by instrumented library (e.g. ServiceBus or Asp.Net Core)
// and consumed by ApplicationInsights.
Expand Down Expand Up @@ -412,19 +443,12 @@ private void ApplyFunctionResultActivityTags(IEnumerable<KeyValuePair<string, ob
break;
}
}


currentActivity.AddTag(LogConstants.CategoryNameKey, _categoryName);
currentActivity.AddTag(LogConstants.LogLevelKey, logLevel.ToStringOptimized());

if (scope != null)
{
if (scope.TryGetValue(LogConstants.CategoryNameKey, out object category))
{
currentActivity.AddTag(LogConstants.CategoryNameKey, category.ToString());
}

if (scope.TryGetValue(LogConstants.LogLevelKey, out object logLevel))
{
currentActivity.AddTag(LogConstants.LogLevelKey, logLevel.ToString());
}

if (!_loggerOptions.HttpAutoCollectionOptions.EnableHttpTriggerExtendedInfoCollection &&
scope.TryGetValue(ApplicationInsightsScopeKeys.HttpRequest, out var request) &&
request is HttpRequest httpRequest)
Expand All @@ -450,7 +474,6 @@ public IDisposable BeginScope<TState>(TState state)
}

StartTelemetryIfFunctionInvocation(state as IDictionary<string, object>);

return DictionaryLoggerScope.Push(state);
}

Expand Down
Loading