Browse Source

Reduce allocations caused by logging.

pull/3055/head
Dariusz Komosinski 7 years ago
parent
commit
01a404836e
  1. 68
      src/Avalonia.Base/AvaloniaObject.cs
  2. 71
      src/Avalonia.Base/Logging/ILogSink.cs
  3. 90
      src/Avalonia.Base/Logging/Logger.cs
  4. 2
      src/Avalonia.Controls/Primitives/TemplatedControl.cs
  5. 32
      src/Avalonia.Layout/LayoutManager.cs
  6. 8
      src/Avalonia.Layout/Layoutable.cs
  7. 104
      src/Avalonia.Logging.Serilog/SerilogLogger.cs
  8. 4
      src/Avalonia.Visuals/Visual.cs
  9. 32
      tests/Avalonia.UnitTests/TestLogSink.cs

68
src/Avalonia.Base/AvaloniaObject.cs

@ -326,8 +326,6 @@ namespace Avalonia
VerifyAccess(); VerifyAccess();
var description = GetDescription(source);
if (property.IsDirect) if (property.IsDirect)
{ {
if (property.IsReadOnly) if (property.IsReadOnly)
@ -335,12 +333,18 @@ namespace Avalonia
throw new ArgumentException($"The property {property.Name} is readonly."); throw new ArgumentException($"The property {property.Name} is readonly.");
} }
Logger.Verbose( if (Logger.IsEnabled(LogEventLevel.Verbose))
LogArea.Property, {
this, var description = GetDescription(source);
"Bound {Property} to {Binding} with priority LocalValue",
property, Logger.Log(
description); LogEventLevel.Verbose,
LogArea.Property,
this,
"Bound {Property} to {Binding} with priority LocalValue",
property,
description);
}
if (_directBindings == null) if (_directBindings == null)
{ {
@ -351,13 +355,19 @@ namespace Avalonia
} }
else else
{ {
Logger.Verbose( if (Logger.IsEnabled(LogEventLevel.Verbose))
LogArea.Property, {
this, var description = GetDescription(source);
"Bound {Property} to {Binding} with priority {Priority}",
property, Logger.Log(
description, LogEventLevel.Verbose,
priority); LogArea.Property,
this,
"Bound {Property} to {Binding} with priority {Priority}",
property,
description,
priority);
}
return Values.AddBinding(property, source, priority); return Values.AddBinding(property, source, priority);
} }
@ -406,14 +416,18 @@ namespace Avalonia
{ {
RaisePropertyChanged(property, oldValue, newValue, (BindingPriority)priority); RaisePropertyChanged(property, oldValue, newValue, (BindingPriority)priority);
Logger.Verbose( if (Logger.IsEnabled(LogEventLevel.Verbose))
LogArea.Property, {
this, Logger.Log(
"{Property} changed from {$Old} to {$Value} with priority {Priority}", LogEventLevel.Verbose,
property, LogArea.Property,
oldValue, this,
newValue, "{Property} changed from {$Old} to {$Value} with priority {Priority}",
(BindingPriority)priority); property,
oldValue,
newValue,
(BindingPriority)priority);
}
} }
} }
@ -812,7 +826,13 @@ namespace Avalonia
/// <param name="priority">The priority.</param> /// <param name="priority">The priority.</param>
private void LogPropertySet(AvaloniaProperty property, object value, BindingPriority priority) private void LogPropertySet(AvaloniaProperty property, object value, BindingPriority priority)
{ {
Logger.Verbose( if (!Logger.IsEnabled(LogEventLevel.Verbose))
{
return;
}
Logger.Log(
LogEventLevel.Verbose,
LogArea.Property, LogArea.Property,
this, this,
"Set {Property} to {$Value} with priority {Priority}", "Set {Property} to {$Value} with priority {Priority}",

71
src/Avalonia.Base/Logging/ILogSink.cs

@ -8,6 +8,77 @@ namespace Avalonia.Logging
/// </summary> /// </summary>
public interface ILogSink public interface ILogSink
{ {
/// <summary>
/// Checks if given log level is enabled.
/// </summary>
/// <param name="level">The log event level.</param>
/// <returns><see langword="true"/> if given log level is enabled.</returns>
bool IsEnabled(LogEventLevel level);
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
void Log(
LogEventLevel level,
string area,
object source,
string messageTemplate);
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
void Log<T0>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0);
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
/// <param name="propertyValue1">Message property value.</param>
void Log<T0, T1>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1);
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
/// <param name="propertyValue1">Message property value.</param>
/// <param name="propertyValue2">Message property value.</param>
void Log<T0, T1, T2>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1,
T2 propertyValue2);
/// <summary> /// <summary>
/// Logs a new event. /// Logs a new event.
/// </summary> /// </summary>

90
src/Avalonia.Base/Logging/Logger.cs

@ -15,6 +15,96 @@ namespace Avalonia.Logging
/// </summary> /// </summary>
public static ILogSink Sink { get; set; } public static ILogSink Sink { get; set; }
/// <summary>
/// Checks if given log level is enabled.
/// </summary>
/// <param name="level">The log event level.</param>
/// <returns><see langword="true"/> if given log level is enabled.</returns>
public static bool IsEnabled(LogEventLevel level)
{
return Sink?.IsEnabled(level) == true;
}
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void Log(
LogEventLevel level,
string area,
object source,
string messageTemplate)
{
Sink?.Log(level, area, source, messageTemplate);
}
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void Log<T0>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0)
{
Sink?.Log(level, area, source, messageTemplate, propertyValue0);
}
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
/// <param name="propertyValue1">Message property value.</param>
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void Log<T0, T1>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1)
{
Sink?.Log(level, area, source, messageTemplate, propertyValue0, propertyValue1);
}
/// <summary>
/// Logs an event.
/// </summary>
/// <param name="level">The log event level.</param>
/// <param name="area">The area that the event originates.</param>
/// <param name="source">The object from which the event originates.</param>
/// <param name="messageTemplate">The message template.</param>
/// <param name="propertyValue0">Message property value.</param>
/// <param name="propertyValue1">Message property value.</param>
/// <param name="propertyValue2">Message property value.</param>
[MethodImpl(MethodImplOptions.AggressiveInlining)]
public static void Log<T0, T1, T2>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1,
T2 propertyValue2)
{
Sink?.Log(level, area, source, messageTemplate, propertyValue0, propertyValue1, propertyValue2);
}
/// <summary> /// <summary>
/// Logs an event. /// Logs an event.
/// </summary> /// </summary>

2
src/Avalonia.Controls/Primitives/TemplatedControl.cs

@ -255,7 +255,7 @@ namespace Avalonia.Controls.Primitives
if (template != null) if (template != null)
{ {
Logger.Verbose(LogArea.Control, this, "Creating control template"); Logger.Log(LogEventLevel.Verbose, LogArea.Control, this, "Creating control template");
var (child, nameScope) = template.Build(this); var (child, nameScope) = template.Build(this);
ApplyTemplatedParent(child); ApplyTemplatedParent(child);

32
src/Avalonia.Layout/LayoutManager.cs

@ -2,6 +2,7 @@
// Licensed under the MIT license. See licence.md file in the project root for full license information. // Licensed under the MIT license. See licence.md file in the project root for full license information.
using System; using System;
using System.Diagnostics;
using Avalonia.Logging; using Avalonia.Logging;
using Avalonia.Threading; using Avalonia.Threading;
@ -69,15 +70,22 @@ namespace Avalonia.Layout
{ {
_running = true; _running = true;
Logger.Information( Stopwatch stopwatch = null;
LogArea.Layout,
this,
"Started layout pass. To measure: {Measure} To arrange: {Arrange}",
_toMeasure.Count,
_toArrange.Count);
var stopwatch = new System.Diagnostics.Stopwatch(); bool captureTiming = Logger.IsEnabled(LogEventLevel.Information);
stopwatch.Start();
if (captureTiming)
{
Logger.Log(LogEventLevel.Information,
LogArea.Layout,
this,
"Started layout pass. To measure: {Measure} To arrange: {Arrange}",
_toMeasure.Count,
_toArrange.Count);
stopwatch = new Stopwatch();
stopwatch.Start();
}
_toMeasure.BeginLoop(MaxPasses); _toMeasure.BeginLoop(MaxPasses);
_toArrange.BeginLoop(MaxPasses); _toArrange.BeginLoop(MaxPasses);
@ -103,8 +111,12 @@ namespace Avalonia.Layout
_toMeasure.EndLoop(); _toMeasure.EndLoop();
_toArrange.EndLoop(); _toArrange.EndLoop();
stopwatch.Stop(); if (captureTiming)
Logger.Information(LogArea.Layout, this, "Layout pass finished in {Time}", stopwatch.Elapsed); {
stopwatch.Stop();
Logger.Information(LogArea.Layout, this, "Layout pass finished in {Time}", stopwatch.Elapsed);
}
} }
_queued = false; _queued = false;

8
src/Avalonia.Layout/Layoutable.cs

@ -329,7 +329,7 @@ namespace Avalonia.Layout
DesiredSize = desiredSize; DesiredSize = desiredSize;
_previousMeasure = availableSize; _previousMeasure = availableSize;
Logger.Verbose(LogArea.Layout, this, "Measure requested {DesiredSize}", DesiredSize); Logger.Log(LogEventLevel.Verbose, LogArea.Layout, this, "Measure requested {DesiredSize}", DesiredSize);
if (DesiredSize != previousDesiredSize) if (DesiredSize != previousDesiredSize)
{ {
@ -356,7 +356,7 @@ namespace Avalonia.Layout
if (!IsArrangeValid || _previousArrange != rect) if (!IsArrangeValid || _previousArrange != rect)
{ {
Logger.Verbose(LogArea.Layout, this, "Arrange to {Rect} ", rect); Logger.Log(LogEventLevel.Verbose, LogArea.Layout, this, "Arrange to {Rect} ", rect);
IsArrangeValid = true; IsArrangeValid = true;
ArrangeCore(rect); ArrangeCore(rect);
@ -381,7 +381,7 @@ namespace Avalonia.Layout
{ {
if (IsMeasureValid) if (IsMeasureValid)
{ {
Logger.Verbose(LogArea.Layout, this, "Invalidated measure"); Logger.Log(LogEventLevel.Verbose, LogArea.Layout, this, "Invalidated measure");
IsMeasureValid = false; IsMeasureValid = false;
IsArrangeValid = false; IsArrangeValid = false;
@ -402,7 +402,7 @@ namespace Avalonia.Layout
{ {
if (IsArrangeValid) if (IsArrangeValid)
{ {
Logger.Verbose(LogArea.Layout, this, "Invalidated arrange"); Logger.Log(LogEventLevel.Verbose, LogArea.Layout, this, "Invalidated arrange");
IsArrangeValid = false; IsArrangeValid = false;
(VisualRoot as ILayoutRoot)?.LayoutManager?.InvalidateArrange(this); (VisualRoot as ILayoutRoot)?.LayoutManager?.InvalidateArrange(this);

104
src/Avalonia.Logging.Serilog/SerilogLogger.cs

@ -34,6 +34,76 @@ namespace Avalonia.Logging.Serilog
Logger.Sink = new SerilogLogger(output); Logger.Sink = new SerilogLogger(output);
} }
public bool IsEnabled(LogEventLevel level)
{
return _output.IsEnabled((SerilogLogEventLevel)level);
}
public void Log(
LogEventLevel level,
string area,
object source,
string messageTemplate)
{
Contract.Requires<ArgumentNullException>(area != null);
Contract.Requires<ArgumentNullException>(messageTemplate != null);
using (PushLogContextProperties(area, source))
{
_output.Write((SerilogLogEventLevel)level, messageTemplate);
}
}
public void Log<T0>(
LogEventLevel level,
string area, object source,
string messageTemplate,
T0 propertyValue0)
{
Contract.Requires<ArgumentNullException>(area != null);
Contract.Requires<ArgumentNullException>(messageTemplate != null);
using (PushLogContextProperties(area, source))
{
_output.Write((SerilogLogEventLevel)level, messageTemplate, propertyValue0);
}
}
public void Log<T0, T1>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1)
{
Contract.Requires<ArgumentNullException>(area != null);
Contract.Requires<ArgumentNullException>(messageTemplate != null);
using (PushLogContextProperties(area, source))
{
_output.Write((SerilogLogEventLevel)level, messageTemplate, propertyValue0, propertyValue1);
}
}
public void Log<T0, T1, T2>(
LogEventLevel level,
string area,
object source,
string messageTemplate,
T0 propertyValue0,
T1 propertyValue1,
T2 propertyValue2)
{
Contract.Requires<ArgumentNullException>(area != null);
Contract.Requires<ArgumentNullException>(messageTemplate != null);
using (PushLogContextProperties(area, source))
{
_output.Write((SerilogLogEventLevel)level, messageTemplate, propertyValue0, propertyValue1, propertyValue2);
}
}
/// <inheritdoc/> /// <inheritdoc/>
public void Log( public void Log(
AvaloniaLogEventLevel level, AvaloniaLogEventLevel level,
@ -45,12 +115,40 @@ namespace Avalonia.Logging.Serilog
Contract.Requires<ArgumentNullException>(area != null); Contract.Requires<ArgumentNullException>(area != null);
Contract.Requires<ArgumentNullException>(messageTemplate != null); Contract.Requires<ArgumentNullException>(messageTemplate != null);
using (LogContext.PushProperty("Area", area)) using (PushLogContextProperties(area, source))
using (LogContext.PushProperty("SourceType", source?.GetType()))
using (LogContext.PushProperty("SourceHash", source?.GetHashCode()))
{ {
_output.Write((SerilogLogEventLevel)level, messageTemplate, propertyValues); _output.Write((SerilogLogEventLevel)level, messageTemplate, propertyValues);
} }
} }
private static LogContextDisposable PushLogContextProperties(string area, object source)
{
return new LogContextDisposable(
LogContext.PushProperty("Area", area),
LogContext.PushProperty("SourceType", source?.GetType()),
LogContext.PushProperty("SourceHash", source?.GetHashCode())
);
}
private readonly struct LogContextDisposable : IDisposable
{
private readonly IDisposable _areaDisposable;
private readonly IDisposable _sourceTypeDisposable;
private readonly IDisposable _sourceHashDisposable;
public LogContextDisposable(IDisposable areaDisposable, IDisposable sourceTypeDisposable, IDisposable sourceHashDisposable)
{
_areaDisposable = areaDisposable;
_sourceTypeDisposable = sourceTypeDisposable;
_sourceHashDisposable = sourceHashDisposable;
}
public void Dispose()
{
_areaDisposable.Dispose();
_sourceTypeDisposable.Dispose();
_sourceHashDisposable.Dispose();
}
}
} }
} }

4
src/Avalonia.Visuals/Visual.cs

@ -359,7 +359,7 @@ namespace Avalonia
/// <param name="e">The event args.</param> /// <param name="e">The event args.</param>
protected virtual void OnAttachedToVisualTreeCore(VisualTreeAttachmentEventArgs e) protected virtual void OnAttachedToVisualTreeCore(VisualTreeAttachmentEventArgs e)
{ {
Logger.Verbose(LogArea.Visual, this, "Attached to visual tree"); Logger.Log(LogEventLevel.Verbose, LogArea.Visual, this, "Attached to visual tree");
_visualRoot = e.Root; _visualRoot = e.Root;
@ -388,7 +388,7 @@ namespace Avalonia
/// <param name="e">The event args.</param> /// <param name="e">The event args.</param>
protected virtual void OnDetachedFromVisualTreeCore(VisualTreeAttachmentEventArgs e) protected virtual void OnDetachedFromVisualTreeCore(VisualTreeAttachmentEventArgs e)
{ {
Logger.Verbose(LogArea.Visual, this, "Detached from visual tree"); Logger.Log(LogEventLevel.Verbose, LogArea.Visual, this, "Detached from visual tree");
_visualRoot = null; _visualRoot = null;

32
tests/Avalonia.UnitTests/TestLogSink.cs

@ -16,7 +16,7 @@ namespace Avalonia.UnitTests
public class TestLogSink : ILogSink public class TestLogSink : ILogSink
{ {
private LogCallback _callback; private readonly LogCallback _callback;
public TestLogSink(LogCallback callback) public TestLogSink(LogCallback callback)
{ {
@ -30,7 +30,35 @@ namespace Avalonia.UnitTests
return Disposable.Create(() => Logger.Sink = null); return Disposable.Create(() => Logger.Sink = null);
} }
public void Log(LogEventLevel level, string area, object source, string messageTemplate, params object[] propertyValues) public bool IsEnabled(LogEventLevel level)
{
return true;
}
public void Log(LogEventLevel level, string area, object source, string messageTemplate)
{
_callback(level, area, source, messageTemplate);
}
public void Log<T0>(LogEventLevel level, string area, object source, string messageTemplate, T0 propertyValue0)
{
_callback(level, area, source, messageTemplate, propertyValue0);
}
public void Log<T0, T1>(LogEventLevel level, string area, object source, string messageTemplate,
T0 propertyValue0, T1 propertyValue1)
{
_callback(level, area, source, messageTemplate, propertyValue0, propertyValue1);
}
public void Log<T0, T1, T2>(LogEventLevel level, string area, object source, string messageTemplate,
T0 propertyValue0, T1 propertyValue1, T2 propertyValue2)
{
_callback(level, area, source, messageTemplate, propertyValue0, propertyValue1, propertyValue2);
}
public void Log(LogEventLevel level, string area, object source, string messageTemplate,
params object[] propertyValues)
{ {
_callback(level, area, source, messageTemplate, propertyValues); _callback(level, area, source, messageTemplate, propertyValues);
} }

Loading…
Cancel
Save