Skip to content

Commit

Permalink
Performance Improvements - Logging (#2946)
Browse files Browse the repository at this point in the history 
Performance Improvements - AI Logging pipeline
  • Loading branch information
@RohitRanjanMS
RohitRanjanMS authored Apr 4, 2023
1 parent 9efa258 commit 85485d4
Show file tree
Hide file tree
Showing 6 changed files with 257 additions and 160 deletions.
215 changes: 119 additions & 96 deletions src/Microsoft.Azure.WebJobs.Logging.ApplicationInsights/ApplicationInsightsLogger.cs
View file
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);
}
}

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

0 comments on commit 85485d4

Please sign in to comment.