From 07656ead4680fd62dd200dff29973644a2f4a0cd Mon Sep 17 00:00:00 2001 From: Shay Rojansky Date: Thu, 6 Aug 2020 21:21:01 +0300 Subject: [PATCH] Implement perf counters (#21912) Closes #18016 --- ...ingExpressionVisitor.QueryingEnumerable.cs | 5 + ...ssionVisitor.ReadItemQueryingEnumerable.cs | 5 + ...ingExpressionVisitor.QueryingEnumerable.cs | 3 + .../Internal/FromSqlQueryingEnumerable.cs | 5 + .../Internal/SingleQueryingEnumerable.cs | 5 + .../Query/Internal/SplitQueryingEnumerable.cs | 5 + .../ChangeTracking/Internal/StateManager.cs | 2 + src/EFCore/DbContext.cs | 6 + .../EntityFrameworkEventSource.cs | 191 ++++++++++++++++++ .../Query/Internal/CompiledQueryCache.cs | 10 +- src/EFCore/Storage/ExecutionStrategy.cs | 3 + 11 files changed, 239 insertions(+), 1 deletion(-) create mode 100644 src/EFCore/Infrastructure/EntityFrameworkEventSource.cs diff --git a/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs b/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs index a58c2834b2e..fe00deabf3f 100644 --- a/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs +++ b/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs @@ -10,6 +10,7 @@ using Microsoft.EntityFrameworkCore.Cosmos.Internal; using Microsoft.EntityFrameworkCore.Cosmos.Storage.Internal; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Query; using Newtonsoft.Json.Linq; @@ -138,6 +139,8 @@ public bool MoveNext() { var sqlQuery = _queryingEnumerable.GenerateQuery(); + EntityFrameworkEventSource.Log.QueryExecuting(); + _enumerator = _cosmosQueryContext.CosmosClient .ExecuteSqlQuery( _selectExpression.Container, @@ -213,6 +216,8 @@ public async ValueTask MoveNextAsync() { var sqlQuery = _queryingEnumerable.GenerateQuery(); + EntityFrameworkEventSource.Log.QueryExecuting(); + _enumerator = _cosmosQueryContext.CosmosClient .ExecuteSqlQueryAsync( _selectExpression.Container, diff --git a/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.ReadItemQueryingEnumerable.cs b/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.ReadItemQueryingEnumerable.cs index abfa48aeee5..0327bd298f2 100644 --- a/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.ReadItemQueryingEnumerable.cs +++ b/src/EFCore.Cosmos/Query/Internal/CosmosShapedQueryCompilingExpressionVisitor.ReadItemQueryingEnumerable.cs @@ -12,6 +12,7 @@ using Microsoft.EntityFrameworkCore.Cosmos.Internal; using Microsoft.EntityFrameworkCore.Cosmos.Storage.Internal; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Internal; using Microsoft.EntityFrameworkCore.Metadata; using Microsoft.EntityFrameworkCore.Metadata.Conventions; @@ -110,6 +111,8 @@ public bool MoveNext() throw new InvalidOperationException(CosmosStrings.ParitionKeyMissing); } + EntityFrameworkEventSource.Log.QueryExecuting(); + _item = _cosmosQueryContext.CosmosClient.ExecuteReadItem( _readItemExpression.Container, partitionKey, @@ -148,6 +151,8 @@ public async ValueTask MoveNextAsync() throw new InvalidOperationException(CosmosStrings.ParitionKeyMissing); } + EntityFrameworkEventSource.Log.QueryExecuting(); + _item = await _cosmosQueryContext.CosmosClient.ExecuteReadItemAsync( _readItemExpression.Container, partitionKey, diff --git a/src/EFCore.InMemory/Query/Internal/InMemoryShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs b/src/EFCore.InMemory/Query/Internal/InMemoryShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs index f8575da7452..35f00489dab 100644 --- a/src/EFCore.InMemory/Query/Internal/InMemoryShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs +++ b/src/EFCore.InMemory/Query/Internal/InMemoryShapedQueryCompilingExpressionVisitor.QueryingEnumerable.cs @@ -7,6 +7,7 @@ using System.Threading; using System.Threading.Tasks; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.InMemory.Internal; using Microsoft.EntityFrameworkCore.Query; using Microsoft.EntityFrameworkCore.Storage; @@ -121,6 +122,8 @@ private bool MoveNextHelper() { if (_enumerator == null) { + EntityFrameworkEventSource.Log.QueryExecuting(); + _enumerator = _innerEnumerable.GetEnumerator(); _queryContext.InitializeStateManager(_standAloneStateManager); } diff --git a/src/EFCore.Relational/Query/Internal/FromSqlQueryingEnumerable.cs b/src/EFCore.Relational/Query/Internal/FromSqlQueryingEnumerable.cs index eda28dae6a9..9b8be9102cf 100644 --- a/src/EFCore.Relational/Query/Internal/FromSqlQueryingEnumerable.cs +++ b/src/EFCore.Relational/Query/Internal/FromSqlQueryingEnumerable.cs @@ -10,6 +10,7 @@ using System.Threading.Tasks; using JetBrains.Annotations; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Storage; namespace Microsoft.EntityFrameworkCore.Query.Internal @@ -191,6 +192,8 @@ public bool MoveNext() private bool InitializeReader(DbContext _, bool result) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader @@ -279,6 +282,8 @@ await _relationalQueryContext.ExecutionStrategyFactory.Create() private async Task InitializeReaderAsync(DbContext _, bool result, CancellationToken cancellationToken) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader diff --git a/src/EFCore.Relational/Query/Internal/SingleQueryingEnumerable.cs b/src/EFCore.Relational/Query/Internal/SingleQueryingEnumerable.cs index 6096ead7e77..4df26672b7d 100644 --- a/src/EFCore.Relational/Query/Internal/SingleQueryingEnumerable.cs +++ b/src/EFCore.Relational/Query/Internal/SingleQueryingEnumerable.cs @@ -9,6 +9,7 @@ using System.Threading.Tasks; using JetBrains.Annotations; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Storage; namespace Microsoft.EntityFrameworkCore.Query.Internal @@ -184,6 +185,8 @@ public bool MoveNext() private bool InitializeReader(DbContext _, bool result) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader @@ -296,6 +299,8 @@ await _relationalQueryContext.ExecutionStrategyFactory.Create() private async Task InitializeReaderAsync(DbContext _, bool result, CancellationToken cancellationToken) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader diff --git a/src/EFCore.Relational/Query/Internal/SplitQueryingEnumerable.cs b/src/EFCore.Relational/Query/Internal/SplitQueryingEnumerable.cs index 29c375aa574..114e2ade21f 100644 --- a/src/EFCore.Relational/Query/Internal/SplitQueryingEnumerable.cs +++ b/src/EFCore.Relational/Query/Internal/SplitQueryingEnumerable.cs @@ -9,6 +9,7 @@ using System.Threading.Tasks; using JetBrains.Annotations; using Microsoft.EntityFrameworkCore.Diagnostics; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Storage; namespace Microsoft.EntityFrameworkCore.Query.Internal @@ -182,6 +183,8 @@ public bool MoveNext() private bool InitializeReader(DbContext _, bool result) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader @@ -286,6 +289,8 @@ public async ValueTask MoveNextAsync() private async Task InitializeReaderAsync(DbContext _, bool result, CancellationToken cancellationToken) { + EntityFrameworkEventSource.Log.QueryExecuting(); + var relationalCommand = _relationalCommandCache.GetRelationalCommand(_relationalQueryContext.ParameterValues); _dataReader diff --git a/src/EFCore/ChangeTracking/Internal/StateManager.cs b/src/EFCore/ChangeTracking/Internal/StateManager.cs index 2d454a0ea43..35a2a57979c 100644 --- a/src/EFCore/ChangeTracking/Internal/StateManager.cs +++ b/src/EFCore/ChangeTracking/Internal/StateManager.cs @@ -1072,6 +1072,8 @@ protected virtual int SaveChanges( { using (_concurrencyDetector.EnterCriticalSection()) { + EntityFrameworkEventSource.Log.SavingChanges(); + return _database.SaveChanges(entriesToSave); } } diff --git a/src/EFCore/DbContext.cs b/src/EFCore/DbContext.cs index 2af5f7d74e1..ac593d65f93 100644 --- a/src/EFCore/DbContext.cs +++ b/src/EFCore/DbContext.cs @@ -340,6 +340,8 @@ private IServiceProvider InternalServiceProvider { _initializing = true; + EntityFrameworkEventSource.Log.DbContextInitializing(); + var optionsBuilder = new DbContextOptionsBuilder(_options); OnConfiguring(optionsBuilder); @@ -506,6 +508,8 @@ public virtual int SaveChanges(bool acceptAllChangesOnSuccess) } catch (DbUpdateConcurrencyException exception) { + EntityFrameworkEventSource.Log.OptimisticConcurrencyFailure(); + DbContextDependencies.UpdateLogger.OptimisticConcurrencyException(this, exception); SaveChangesFailed?.Invoke(this, new SaveChangesFailedEventArgs(acceptAllChangesOnSuccess, exception)); @@ -815,6 +819,8 @@ private bool DisposeSync() } else if (!_disposed) { + EntityFrameworkEventSource.Log.DbContextDisposing(); + _dbContextDependencies?.InfrastructureLogger.ContextDisposed(this); _disposed = true; diff --git a/src/EFCore/Infrastructure/EntityFrameworkEventSource.cs b/src/EFCore/Infrastructure/EntityFrameworkEventSource.cs new file mode 100644 index 00000000000..190f81c3956 --- /dev/null +++ b/src/EFCore/Infrastructure/EntityFrameworkEventSource.cs @@ -0,0 +1,191 @@ +// Copyright (c) .NET Foundation. All rights reserved. +// Licensed under the Apache License, Version 2.0. See License.txt in the project root for license information. + +using System; +using System.Diagnostics.Tracing; +using System.Runtime.InteropServices; +using System.Threading; +using Microsoft.EntityFrameworkCore.Storage; + +namespace Microsoft.EntityFrameworkCore.Infrastructure +{ + /// + /// An emitting Entity Framework performance counter data. + /// + public sealed class EntityFrameworkEventSource : EventSource + { + private long _activeDbContexts, _totalQueries, _totalSaveChanges; + private long _totalExecutionStrategyOperationFailures, _totalOptimisticConcurrencyFailures; + private CacheInfo _compiledQueryCacheInfo; + + // ReSharper disable NotAccessedField.Local + private PollingCounter _activeDbContextsCounter; + private PollingCounter _totalQueriesCounter; + private IncrementingPollingCounter _queriesPerSecondCounter; + private PollingCounter _totalSaveChangesCounter; + private IncrementingPollingCounter _saveChangesPerSecondCounter; + private PollingCounter _compiledQueryCacheHitRateCounter; + private PollingCounter _totalExecutionStrategyOperationFailuresCounter; + private IncrementingPollingCounter _executionStrategyOperationFailuresPerSecondCounter; + private PollingCounter _totalOptimisticConcurrencyFailuresCounter; + private IncrementingPollingCounter _optimisticConcurrencyFailuresPerSecondCounter; + // ReSharper restore NotAccessedField.Local + + /// + /// The singleton instance of . + /// + public static readonly EntityFrameworkEventSource Log = new EntityFrameworkEventSource(); + + private EntityFrameworkEventSource() : base("Microsoft.EntityFrameworkCore") {} + + /// + /// Indicates that a new instance is being initialized. + /// + public void DbContextInitializing() => Interlocked.Increment(ref _activeDbContexts); + + /// + /// Indicates that a instance is being disposed. + /// + public void DbContextDisposing() => Interlocked.Decrement(ref _activeDbContexts); + + /// + /// Indicates that a query is about to begin execution. + /// + public void QueryExecuting() => Interlocked.Increment(ref _totalQueries); + + /// + /// Indicates that changes are about to be saved. + /// + public void SavingChanges() => Interlocked.Increment(ref _totalSaveChanges); + + /// + /// Indicates a hit in the compiled query cache, signifying that query compilation will not need to occur. + /// + public void CompiledQueryCacheHit() => Interlocked.Increment(ref _compiledQueryCacheInfo.Hits); + + /// + /// Indicates a miss in the compiled query cache, signifying that query compilation will need to occur. + /// + public void CompiledQueryCacheMiss() => Interlocked.Increment(ref _compiledQueryCacheInfo.Misses); + + /// + /// Indicates that an operation executed by an failed (and may be retried). + /// + public void ExecutionStrategyOperationFailure() => Interlocked.Increment(ref _totalExecutionStrategyOperationFailures); + + /// + /// Indicates that an optimistic concurrency failure has occurred. + /// + public void OptimisticConcurrencyFailure() => Interlocked.Increment(ref _totalOptimisticConcurrencyFailures); + + /// + protected override void OnEventCommand(EventCommandEventArgs command) + { + if (command.Command == EventCommand.Enable) + { + // Comment taken from RuntimeEventSource in CoreCLR + // NOTE: These counters will NOT be disposed on disable command because we may be introducing + // a race condition by doing that. We still want to create these lazily so that we aren't adding + // overhead by at all times even when counters aren't enabled. + // On disable, PollingCounters will stop polling for values so it should be fine to leave them around. + + _activeDbContextsCounter ??= new PollingCounter("active-db-contexts", this, () => _activeDbContexts) + { + DisplayName = "Active DbContexts" + }; + + _totalQueriesCounter ??= new PollingCounter("total-queries", this, () => _totalQueries) + { + DisplayName = "Queries (Total)" + }; + + _queriesPerSecondCounter ??= new IncrementingPollingCounter( + "queries-per-second", + this, + () => _totalQueries) + { + DisplayName = "Queries", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalSaveChangesCounter ??= new PollingCounter("total-save-changes", this, () => _totalSaveChanges) + { + DisplayName = "SaveChanges (Total)" + }; + + _saveChangesPerSecondCounter ??= new IncrementingPollingCounter( + "save-changes-per-second", + this, + () => _totalSaveChanges) + { + DisplayName = "SaveChanges", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _compiledQueryCacheHitRateCounter ??= new PollingCounter( + "compiled-query-cache-hit-rate", + this, + () => _compiledQueryCacheInfo.CalculateAndReset()) + { + DisplayName = "Query Cache Hit Rate", DisplayUnits = "%" + }; + + _totalExecutionStrategyOperationFailuresCounter ??= new PollingCounter( + "total-execution-strategy-operation-failures", + this, + () => _totalExecutionStrategyOperationFailures) + { + DisplayName = "Execution Strategy Operation Failures (Total)" + }; + + _executionStrategyOperationFailuresPerSecondCounter ??= new IncrementingPollingCounter( + "execution-strategy-operation-failures-per-second", + this, + () => _totalExecutionStrategyOperationFailures) + { + DisplayName = "Execution Strategy Operation Failures", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + + _totalOptimisticConcurrencyFailuresCounter ??= new PollingCounter( + "total-optimistic-concurrency-failures", + this, + () => _totalOptimisticConcurrencyFailures) + { + DisplayName = "Optimistic Concurrency Failures (Total)" + }; + + _optimisticConcurrencyFailuresPerSecondCounter ??= new IncrementingPollingCounter( + "optimistic-concurrency-failures-per-second", + this, + () => _totalOptimisticConcurrencyFailures) + { + DisplayName = "Optimistic Concurrency Failures", + DisplayRateTimeScale = TimeSpan.FromSeconds(1) + }; + } + } + + [StructLayout(LayoutKind.Explicit)] + private struct CacheInfo + { + [FieldOffset(0)] + internal int Hits; + [FieldOffset(4)] + internal int Misses; + + [FieldOffset(0)] + private long _all; + + /// + /// Returns the atomically-calculated hit rate and atomically resets and to 0. + /// + internal double CalculateAndReset() + { + var clone = new CacheInfo { _all = Volatile.Read(ref _all) }; + Volatile.Write(ref _all, 0); + return ((double)clone.Hits / (clone.Hits + clone.Misses)) * 100; + } + } + } +} diff --git a/src/EFCore/Query/Internal/CompiledQueryCache.cs b/src/EFCore/Query/Internal/CompiledQueryCache.cs index 0ba038098ee..ad3935d098d 100644 --- a/src/EFCore/Query/Internal/CompiledQueryCache.cs +++ b/src/EFCore/Query/Internal/CompiledQueryCache.cs @@ -7,6 +7,7 @@ using System.Threading; using System.Threading.Tasks; using JetBrains.Annotations; +using Microsoft.EntityFrameworkCore.Infrastructure; using Microsoft.EntityFrameworkCore.Utilities; using Microsoft.Extensions.Caching.Memory; using Microsoft.Extensions.DependencyInjection; @@ -54,6 +55,7 @@ public virtual Func GetOrAddQuery( // ReSharper disable once InconsistentlySynchronizedField if (_memoryCache.TryGetValue(cacheKey, out Func compiledQuery)) { + EntityFrameworkEventSource.Log.CompiledQueryCacheHit(); return compiledQuery; } @@ -66,8 +68,14 @@ public virtual Func GetOrAddQuery( { lock (compilationLock) { - if (!_memoryCache.TryGetValue(cacheKey, out compiledQuery)) + if (_memoryCache.TryGetValue(cacheKey, out compiledQuery)) { + EntityFrameworkEventSource.Log.CompiledQueryCacheHit(); + } + else + { + EntityFrameworkEventSource.Log.CompiledQueryCacheMiss(); + compiledQuery = compiler(); _memoryCache.Set(cacheKey, compiledQuery, new MemoryCacheEntryOptions { Size = 10 }); } diff --git a/src/EFCore/Storage/ExecutionStrategy.cs b/src/EFCore/Storage/ExecutionStrategy.cs index 5d946582b61..d7d4035c5b3 100644 --- a/src/EFCore/Storage/ExecutionStrategy.cs +++ b/src/EFCore/Storage/ExecutionStrategy.cs @@ -176,6 +176,9 @@ private TResult ExecuteImplementation( catch (Exception ex) { Suspended = false; + + EntityFrameworkEventSource.Log.ExecutionStrategyOperationFailure(); + if (verifySucceeded != null && CallOnWrappedException(ex, ShouldVerifySuccessOn)) {