Skip to content

Commit fd0c221

Browse files
committed
Implement event counters
Also exposed some logic issues/bugs which were fixed. Closes #1725
1 parent c6df4e0 commit fd0c221

File tree

10 files changed

+305
-48
lines changed

10 files changed

+305
-48
lines changed

src/Npgsql/Counters.cs

Lines changed: 11 additions & 8 deletions
Original file line numberDiff line numberDiff line change
@@ -61,10 +61,10 @@ internal static void Initialize(bool usePerfCounters)
6161
var enabled = false;
6262
var expensiveEnabled = false;
6363

64-
#if NET461
65-
try
64+
if (usePerfCounters)
6665
{
67-
if (usePerfCounters)
66+
#if NET461
67+
try
6868
{
6969
enabled = PerformanceCounterCategory.Exists(Counter.DiagnosticsCounterCategory);
7070
if (!enabled)
@@ -73,12 +73,15 @@ internal static void Initialize(bool usePerfCounters)
7373
"level of detail to track with connection pool performance counters");
7474
expensiveEnabled = enabled && perfCtrSwitch.Level == TraceLevel.Verbose;
7575
}
76-
}
77-
catch (Exception e)
78-
{
79-
Log.Debug("Exception while checking for performance counter category (counters will be disabled)", e);
80-
}
76+
catch (Exception e)
77+
{
78+
Log.Debug("Exception while checking for performance counter category (counters will be disabled)", e);
79+
}
80+
#else
81+
throw new NotSupportedException("The legacy Windows Performance Counters are only supported on .NET Framework. " +
82+
"The new .NET Core performance counter feature (EventSource) doesn't require any connection string parameters.");
8183
#endif
84+
}
8285

8386
try
8487
{

src/Npgsql/NpgsqlCommand.cs

Lines changed: 47 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -831,6 +831,9 @@ await connector.WriteBind(
831831
}
832832

833833
await connector.WriteExecute(0, async);
834+
835+
if (pStatement != null)
836+
pStatement.LastUsed = DateTime.UtcNow;
834837
}
835838

836839
await connector.WriteSync(async);
@@ -1085,73 +1088,79 @@ async ValueTask<DbDataReader> ExecuteDbDataReader(CommandBehavior behavior, bool
10851088
{
10861089
ValidateParameters(connector.TypeMapper);
10871090

1088-
if (IsExplicitlyPrepared)
1091+
switch (IsExplicitlyPrepared)
10891092
{
1093+
case true:
10901094
Debug.Assert(_connectorPreparedOn != null);
10911095
if (_connectorPreparedOn != connector)
10921096
{
10931097
// The command was prepared, but since then the connector has changed. Detach all prepared statements.
10941098
foreach (var s in _statements)
10951099
s.PreparedStatement = null;
10961100
ResetExplicitPreparation();
1097-
ProcessRawQuery();
1101+
goto case false;
10981102
}
1099-
}
1100-
else
1101-
ProcessRawQuery();
1102-
1103-
State = CommandState.InProgress;
1104-
1105-
if (Log.IsEnabled(NpgsqlLogLevel.Debug))
1106-
LogCommand(connector.Id);
1107-
Task sendTask;
1108-
1109-
// If a cancellation is in progress, wait for it to "complete" before proceeding (#615)
1110-
lock (connector.CancelLock) { }
1103+
NpgsqlEventSource.Log.CommandStartPrepared();
1104+
break;
11111105

1112-
connector.UserTimeout = CommandTimeout * 1000;
1106+
case false:
1107+
ProcessRawQuery();
11131108

1114-
if ((behavior & CommandBehavior.SchemaOnly) == 0)
1115-
{
11161109
if (connector.Settings.MaxAutoPrepare > 0)
11171110
{
1111+
var numPrepared = 0;
11181112
foreach (var statement in _statements)
11191113
{
11201114
// If this statement isn't prepared, see if it gets implicitly prepared.
11211115
// Note that this may return null (not enough usages for automatic preparation).
11221116
if (!statement.IsPrepared)
1123-
statement.PreparedStatement =
1124-
connector.PreparedStatementManager.TryGetAutoPrepared(statement);
1117+
statement.PreparedStatement = connector.PreparedStatementManager.TryGetAutoPrepared(statement);
11251118
if (statement.PreparedStatement != null)
1126-
statement.PreparedStatement.LastUsed = DateTime.UtcNow;
1119+
numPrepared++;
11271120
}
1128-
_connectorPreparedOn = connector;
1129-
}
11301121

1131-
// We do not wait for the entire send to complete before proceeding to reading -
1132-
// the sending continues in parallel with the user's reading. Waiting for the
1133-
// entire send to complete would trigger a deadlock for multi-statement commands,
1134-
// where PostgreSQL sends large results for the first statement, while we're sending large
1135-
// parameter data for the second. See #641.
1136-
// Instead, all sends for non-first statements and for non-first buffers are performed
1137-
// asynchronously (even if the user requested sync), in a special synchronization context
1138-
// to prevents a dependency on the thread pool (which would also trigger deadlocks).
1139-
// The WriteBuffer notifies this command when the first buffer flush occurs, so that the
1140-
// send functions can switch to the special async mode when needed.
1141-
sendTask = SendExecute(connector, async);
1142-
}
1143-
else
1144-
{
1145-
sendTask = SendExecuteSchemaOnly(connector, async);
1122+
if (numPrepared > 0)
1123+
{
1124+
_connectorPreparedOn = connector;
1125+
if (numPrepared == _statements.Count)
1126+
NpgsqlEventSource.Log.CommandStartPrepared();
1127+
}
1128+
}
1129+
break;
11461130
}
11471131

1132+
State = CommandState.InProgress;
1133+
1134+
if (Log.IsEnabled(NpgsqlLogLevel.Debug))
1135+
LogCommand(connector.Id);
1136+
NpgsqlEventSource.Log.CommandStart(CommandText);
1137+
Task sendTask;
1138+
1139+
// If a cancellation is in progress, wait for it to "complete" before proceeding (#615)
1140+
lock (connector.CancelLock) { }
1141+
1142+
connector.UserTimeout = CommandTimeout * 1000;
1143+
1144+
// We do not wait for the entire send to complete before proceeding to reading -
1145+
// the sending continues in parallel with the user's reading. Waiting for the
1146+
// entire send to complete would trigger a deadlock for multi-statement commands,
1147+
// where PostgreSQL sends large results for the first statement, while we're sending large
1148+
// parameter data for the second. See #641.
1149+
// Instead, all sends for non-first statements and for non-first buffers are performed
1150+
// asynchronously (even if the user requested sync), in a special synchronization context
1151+
// to prevents a dependency on the thread pool (which would also trigger deadlocks).
1152+
// The WriteBuffer notifies this command when the first buffer flush occurs, so that the
1153+
// send functions can switch to the special async mode when needed.
1154+
sendTask = (behavior & CommandBehavior.SchemaOnly) == 0
1155+
? SendExecute(connector, async)
1156+
: SendExecuteSchemaOnly(connector, async);
1157+
11481158
// The following is a hack. It raises an exception if one was thrown in the first phases
11491159
// of the send (i.e. in parts of the send that executed synchronously). Exceptions may
11501160
// still happen later and aren't properly handled. See #1323.
11511161
if (sendTask.IsFaulted)
11521162
sendTask.GetAwaiter().GetResult();
11531163

1154-
//var reader = new NpgsqlDataReader(this, behavior, _statements, sendTask);
11551164
var reader = connector.DataReader;
11561165
reader.Init(this, behavior, _statements, sendTask);
11571166
connector.CurrentReader = reader;

src/Npgsql/NpgsqlConnection.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -177,6 +177,7 @@ void GetPoolAndSettings()
177177
// If the pool we created was the one that ended up being stored we need to increment the appropriate counter.
178178
// Avoids a race condition where multiple threads will create a pool but only one will be stored.
179179
Counters.NumberOfActiveConnectionPools.Increment();
180+
NpgsqlEventSource.Log.PoolCreated();
180181
}
181182

182183
_pool = PoolManager.GetOrAdd(_connectionString, _pool);

src/Npgsql/NpgsqlConnector.cs

Lines changed: 4 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -922,7 +922,11 @@ internal ValueTask<IBackendMessage> ReadMessage(bool async, DataRowLoadingMode d
922922

923923
case BackendMessageCode.ReadyForQuery:
924924
if (error != null)
925+
{
926+
NpgsqlEventSource.Log.CommandFailed();
925927
throw error;
928+
}
929+
926930
break;
927931

928932
// Asynchronous messages which can come anytime, they have already been handled

src/Npgsql/NpgsqlDataReader.cs

Lines changed: 1 addition & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -816,6 +816,7 @@ internal async Task Cleanup(bool async, bool connectionClosing=false)
816816
Command.State = CommandState.Idle;
817817
Connector.CurrentReader = null;
818818
Connector.EndUserAction();
819+
NpgsqlEventSource.Log.CommandStop();
819820

820821
// If the reader is being closed as part of the connection closing, we don't apply
821822
// the reader's CommandBehavior.CloseConnection

src/Npgsql/NpgsqlEventSource.cs

Lines changed: 178 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,178 @@
1+
using System;
2+
using System.Threading;
3+
using System.Diagnostics.Tracing;
4+
using System.Runtime.CompilerServices;
5+
6+
namespace Npgsql
7+
{
8+
sealed class NpgsqlEventSource : EventSource
9+
{
10+
public static readonly NpgsqlEventSource Log = new NpgsqlEventSource();
11+
12+
const string EventSourceName = "Npgsql";
13+
14+
internal const int CommandStartId = 3;
15+
internal const int CommandStopId = 4;
16+
17+
#if !NET461 && !NETSTANDARD2_0
18+
IncrementingPollingCounter? _bytesWrittenPerSecondCounter;
19+
IncrementingPollingCounter? _bytesReadPerSecondCounter;
20+
21+
IncrementingPollingCounter? _commandsPerSecondCounter;
22+
PollingCounter? _totalCommandsCounter;
23+
PollingCounter? _failedCommandsCounter;
24+
PollingCounter? _currentCommandsCounter;
25+
PollingCounter? _preparedCommandsRatioCounter;
26+
27+
PollingCounter? _poolsCounter;
28+
PollingCounter? _idleConnectionsCounter;
29+
PollingCounter? _busyConnectionsCounter;
30+
#endif
31+
long _bytesWritten;
32+
long _bytesRead;
33+
34+
long _totalCommands;
35+
long _totalPreparedCommands;
36+
long _currentCommands;
37+
long _failedCommands;
38+
39+
int _pools;
40+
41+
internal NpgsqlEventSource() : base(EventSourceName) {}
42+
43+
// NOTE
44+
// - The 'Start' and 'Stop' suffixes on the following event names have special meaning in EventSource. They
45+
// enable creating 'activities'.
46+
// For more information, take a look at the following blog post:
47+
// https://blogs.msdn.microsoft.com/vancem/2015/09/14/exploring-eventsource-activity-correlation-and-causation-features/
48+
// - A stop event's event id must be next one after its start event.
49+
50+
internal void BytesWritten(long bytesWritten) => Interlocked.Add(ref _bytesWritten, bytesWritten);
51+
internal void BytesRead(long bytesRead) => Interlocked.Add(ref _bytesRead, bytesRead);
52+
53+
[Event(CommandStartId, Level = EventLevel.Informational)]
54+
public void CommandStart(string sql)
55+
{
56+
Interlocked.Increment(ref _totalCommands);
57+
Interlocked.Increment(ref _currentCommands);
58+
WriteEvent(CommandStartId, sql);
59+
}
60+
61+
[MethodImpl(MethodImplOptions.NoInlining)]
62+
[Event(CommandStopId, Level = EventLevel.Informational)]
63+
public void CommandStop()
64+
{
65+
Interlocked.Decrement(ref _currentCommands);
66+
WriteEvent(CommandStopId);
67+
}
68+
69+
internal void CommandStartPrepared() => Interlocked.Increment(ref _totalPreparedCommands);
70+
71+
internal void CommandFailed() => Interlocked.Increment(ref _failedCommands);
72+
73+
internal void PoolCreated() => Interlocked.Increment(ref _pools);
74+
75+
#if !NET461 && !NETSTANDARD2_0
76+
static int GetIdleConnections()
77+
{
78+
// Note: there's no attempt here to be coherent in terms of race conditions, especially not with regards
79+
// to different counters. So idle and busy and be unsynchronized, as they're not polled together.
80+
var sum = 0;
81+
foreach (var kv in PoolManager.Pools)
82+
{
83+
var pool = kv.Pool;
84+
if (pool == null)
85+
return sum;
86+
sum += pool.State.Idle;
87+
}
88+
return sum;
89+
}
90+
91+
static int GetBusyConnections()
92+
{
93+
// Note: there's no attempt here to be coherent in terms of race conditions, especially not with regards
94+
// to different counters. So idle and busy and be unsynchronized, as they're not polled together.
95+
var sum = 0;
96+
foreach (var kv in PoolManager.Pools)
97+
{
98+
var pool = kv.Pool;
99+
if (pool == null)
100+
return sum;
101+
sum += pool.State.Busy;
102+
}
103+
return sum;
104+
}
105+
106+
protected override void OnEventCommand(EventCommandEventArgs command)
107+
{
108+
if (command.Command == EventCommand.Enable)
109+
{
110+
// Comment taken from RuntimeEventSource in CoreCLR
111+
// NOTE: These counters will NOT be disposed on disable command because we may be introducing
112+
// a race condition by doing that. We still want to create these lazily so that we aren't adding
113+
// overhead by at all times even when counters aren't enabled.
114+
// On disable, PollingCounters will stop polling for values so it should be fine to leave them around.
115+
116+
_bytesWrittenPerSecondCounter = new IncrementingPollingCounter("bytes-written-per-second", this, () => _bytesWritten)
117+
{
118+
DisplayName = "Bytes Written",
119+
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
120+
};
121+
122+
_bytesReadPerSecondCounter = new IncrementingPollingCounter("bytes-read-per-second", this, () => _bytesRead)
123+
{
124+
DisplayName = "Bytes Read",
125+
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
126+
};
127+
128+
_commandsPerSecondCounter = new IncrementingPollingCounter("commands-per-second", this, () => _totalCommands)
129+
{
130+
DisplayName = "Command Rate",
131+
DisplayRateTimeScale = TimeSpan.FromSeconds(1)
132+
};
133+
134+
_totalCommandsCounter = new PollingCounter("total-commands", this, () => _totalCommands)
135+
{
136+
DisplayName = "Total Commands",
137+
};
138+
139+
_currentCommandsCounter = new PollingCounter("current-commands", this, () => _currentCommands)
140+
{
141+
DisplayName = "Current Commands"
142+
};
143+
144+
_failedCommandsCounter = new PollingCounter("failed-commands", this, () => _failedCommands)
145+
{
146+
DisplayName = "Failed Commands"
147+
};
148+
149+
// _preparedCommandsRatioCounter = new PollingCounter("prepared-commands-ratio", this, () => (double)_totalPreparedCommands / (double)_totalCommands)
150+
_preparedCommandsRatioCounter = new PollingCounter("prepared-commands-ratio", this, () =>
151+
{
152+
Console.WriteLine($"{(double)_totalPreparedCommands} / {(double)_totalCommands}");
153+
return (double)_totalPreparedCommands / (double)_totalCommands;
154+
})
155+
{
156+
DisplayName = "Prepared Commands Ratio",
157+
DisplayUnits = "%"
158+
};
159+
160+
_poolsCounter = new PollingCounter("connection-pools", this, () => _pools)
161+
{
162+
DisplayName = "Connection Pools"
163+
};
164+
165+
_idleConnectionsCounter = new PollingCounter("idle-connections", this, () => GetIdleConnections())
166+
{
167+
DisplayName = "Idle Connections"
168+
};
169+
170+
_busyConnectionsCounter = new PollingCounter("busy-connections", this, () => GetBusyConnections())
171+
{
172+
DisplayName = "Busy Connections"
173+
};
174+
}
175+
}
176+
#endif
177+
}
178+
}

src/Npgsql/NpgsqlReadBuffer.cs

Lines changed: 4 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -123,6 +123,7 @@ async Task EnsureLong()
123123

124124
try
125125
{
126+
var totalRead = 0;
126127
while (count > 0)
127128
{
128129
var toRead = Size - FilledBytes;
@@ -145,7 +146,10 @@ async Task EnsureLong()
145146
throw new EndOfStreamException();
146147
count -= read;
147148
FilledBytes += read;
149+
totalRead += read;
148150
}
151+
152+
NpgsqlEventSource.Log.BytesRead(totalRead);
149153
}
150154
// We have a special case when reading async notifications - a timeout may be normal
151155
// shouldn't be fatal
@@ -163,7 +167,6 @@ async Task EnsureLong()
163167
throw new NpgsqlException("Exception while reading from stream", e);
164168
}
165169
}
166-
167170
}
168171

169172
internal Task ReadMore(bool async) => Ensure(ReadBytesLeft + 1, async);

0 commit comments

Comments
 (0)