Skip to content

Commit 50ac108

Browse files
MartinTGDMartinTGD
authored
Add more logging and remove debug logging (#741)
* Add more logging and remove debug logging * Bump version to 6.0.1
1 parent 7f5fdc1 commit 50ac108

File tree

4 files changed

+40
-38
lines changed

4 files changed

+40
-38
lines changed

‎Directory.build.props

+1-1
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,7 @@
11
<Project>
22
<PropertyGroup>
33
<LangVersion>10.0</LangVersion>
4-
<Version>6.0.0</Version>
4+
<Version>6.0.1</Version>
55
</PropertyGroup>
66
<PropertyGroup>
77
<Authors>Norsk Helsenett SF</Authors>

‎src/Helsenorge.Messaging/Abstractions/AmqpEntityCache.cs

+28-36
Original file line numberDiff line numberDiff line change
@@ -9,6 +9,7 @@
99
using Microsoft.Extensions.Logging;
1010
using System;
1111
using System.Collections.Generic;
12+
using System.Diagnostics;
1213
using System.Linq;
1314
using System.Threading;
1415
using System.Threading.Tasks;
@@ -48,7 +49,7 @@ public class CacheEntry<TE> where TE : T
4849

4950
private const ushort MaxTimeToLiveInSeconds = 600;
5051
private const ushort MaxTrimCountPerRecycle = 256;
51-
52+
5253
private readonly SemaphoreSlim _semaphore = new SemaphoreSlim(1, 1);
5354
private readonly Dictionary<string, CacheEntry<T>> _entries = new Dictionary<string, CacheEntry<T>>();
5455
private readonly string _name;
@@ -81,11 +82,11 @@ protected AmqpEntityCache(string name, uint capacity, ushort timeToLiveInSeconds
8182
throw new ArgumentOutOfRangeException(nameof(timeToLiveInSeconds), $"Argument cannot exceed {MaxTimeToLiveInSeconds}.");
8283
if (maxTrimCountPerRecycle > MaxTrimCountPerRecycle)
8384
throw new ArgumentOutOfRangeException(nameof(maxTrimCountPerRecycle), $"Argument cannot exceed {MaxTrimCountPerRecycle}.");
84-
85+
8586
_name = name;
86-
Capacity = capacity;
87-
_timeToLiveInSeconds = timeToLiveInSeconds;
88-
_maxTrimCountPerRecycle = maxTrimCountPerRecycle;
87+
Capacity = capacity;
88+
_timeToLiveInSeconds = timeToLiveInSeconds;
89+
_maxTrimCountPerRecycle = maxTrimCountPerRecycle;
8990
}
9091

9192
/// <summary>
@@ -108,16 +109,22 @@ public async Task<T> CreateAsync(ILogger logger, string path)
108109
if (_shutdownPending) return null;
109110

110111
CacheEntry<T> entry;
112+
Stopwatch stopwatch = new Stopwatch();
113+
stopwatch.Start();
114+
115+
logger.LogInformation("Start-TrimEntriesAsync");
111116
await TrimEntriesAsync(logger).ConfigureAwait(false); // see if we need to trim entries
117+
logger.LogInformation($"End-TrimEntriesAsync: Execution time: {stopwatch.ElapsedMilliseconds}");
118+
119+
stopwatch.Restart();
120+
logger.LogInformation("Start-AddCacheEntries");
112121
await _semaphore.WaitAsync().ConfigureAwait(false);
113122
try
114123
{
115-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "Start-MessagingEntityCache::Create: Create entry for {Path}", path);
116124
// create an entry if it doesn't exist
117125
if (_entries.ContainsKey(path) == false)
118126
{
119127
// create a new record for this entity
120-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache::Create: Creating entry for {Path}", path);
121128
entry = new CacheEntry<T>()
122129
{
123130
ActiveCount = 1,
@@ -127,28 +134,27 @@ public async Task<T> CreateAsync(ILogger logger, string path)
127134
};
128135
_entries.Add(path, entry);
129136

130-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "End-MessagingEntityCache::Create: Create entry for {Path}. ActiveCount={ActiveCount} CacheEntryCount={CacheEntryCount}", path, entry.ActiveCount, _entries.Count);
131137
return entry.Entity;
132138
}
133139

134140
entry = _entries[path];
135141

136-
if(_incrementActiveCount)
142+
if (_incrementActiveCount)
137143
entry.ActiveCount++;
138144
entry.LastUsed = DateTime.UtcNow;
139-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, $"MessagingEntityCache::Create: Updating entry for {path} ActiveCount={entry.ActiveCount}");
140145

141146
// if this entity previously was closed, we need to create a new instance
142147
if (entry.Entity is { IsClosed: false }) return entry.Entity;
143148

144-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache::Create: Creating new entity for {Path} ActiveCount={ActiveCount}", path, entry.ActiveCount);
145149
entry.Entity = await CreateEntityAsync(logger, path).ConfigureAwait(false);
146150
}
147151
finally
148152
{
149153
_semaphore.Release();
150-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "End-MessagingEntityCache::Create: Create entry for {Path}", path);
151154
}
155+
156+
logger.LogInformation($"End-AddCacheEntries: Execution time: {stopwatch.ElapsedMilliseconds}");
157+
stopwatch.Stop();
152158
return entry.Entity;
153159
}
154160

@@ -165,21 +171,16 @@ public async Task ReleaseAsync(ILogger logger, string path)
165171
await _semaphore.WaitAsync().ConfigureAwait(false);
166172
try
167173
{
168-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "Start-MessagingEntityCache::Release: Path={Path}", path);
169-
170174
if (_entries.TryGetValue(path, out CacheEntry<T> entry) == false)
171175
{
172176
return;
173177
}
174178
// under normal conditions, we just decrease the active count
175-
if(entry.ActiveCount > 0)
179+
if (entry.ActiveCount > 0)
176180
entry.ActiveCount--;
177-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache::Release: Releasing entry for Path={Path} ActiveCount={ActiveCount}", path, entry.ActiveCount);
178181
}
179182
finally
180183
{
181-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "End-MessagingEntityCache::Release: Path={Path}", path);
182-
183184
_semaphore.Release();
184185
}
185186
}
@@ -191,8 +192,6 @@ private static async Task CloseEntityAsync(ILogger logger, CacheEntry<T> entry,
191192
{
192193
try
193194
{
194-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "Start-MessagingEntityCache::CloseEntity: Path={Path} ActiveCount={ActiveCount}", path, entry.ActiveCount);
195-
196195
await entry.Entity.CloseAsync().ConfigureAwait(false);
197196
}
198197
catch (Exception ex)
@@ -204,7 +203,6 @@ private static async Task CloseEntityAsync(ILogger logger, CacheEntry<T> entry,
204203
// Even if we get an exception when we close the Link or Session we need to null the entity or we
205204
// will end up in an unsynchronized state where we reuse the entity.
206205
entry.Entity = null;
207-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "End-MessagingEntityCache::CloseEntity: Path={Path} ActiveCount={ActiveCount}", path, entry.ActiveCount);
208206
}
209207
}
210208
}
@@ -215,7 +213,8 @@ public async Task ShutdownAsync(ILogger logger)
215213
{
216214
_shutdownPending = true;
217215
await _semaphore.WaitAsync().ConfigureAwait(false);
218-
try {
216+
try
217+
{
219218
logger.LogInformation(EventIds.MessagingEntityCacheProcessor, "Shutting down: {CacheName}", _name);
220219

221220
foreach (var key in _entries.Keys)
@@ -235,34 +234,27 @@ private async Task TrimEntriesAsync(ILogger logger)
235234
await _semaphore.WaitAsync().ConfigureAwait(false);
236235
try
237236
{
238-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache: Start-TrimEntries CacheCapacity={CacheCapacity} CacheEntryCount={CacheEntryCount}", Capacity, _entries.Keys.Count);
239-
240237
// we haven't reached our max capacity yet
241238
if (_entries.Keys.Count <= Capacity) return;
242239

243-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache: Trimming entries");
244240
var count = (int)Math.Min(_entries.Keys.Count - Capacity, _maxTrimCountPerRecycle);
245-
241+
246242
// get the oldest n entries
247243
var removal = (from v in _entries.Values
248-
orderby v.LastUsed ascending
249-
where v.Entity != null
250-
&& v.Entity.IsClosed == false
251-
&& v.LastUsed < DateTime.UtcNow.AddSeconds(-_timeToLiveInSeconds)
252-
&& v.ActiveCount == 0
253-
select v).Take(count).ToList();
244+
orderby v.LastUsed ascending
245+
where v.Entity != null
246+
&& v.Entity.IsClosed == false
247+
&& v.LastUsed < DateTime.UtcNow.AddSeconds(-_timeToLiveInSeconds)
248+
&& v.ActiveCount == 0
249+
select v).Take(count).ToList();
254250

255-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache: Trimming entries ActualRemovalCount={ActualRemovalCount} RemovalCount={ProposedRemovalCount} CacheCapacity={CacheCapacity} CacheEntryCount={CacheEntryCount}", removal.Count(), count, Capacity, _entries.Keys.Count);
256-
257251
foreach (var item in removal)
258252
{
259253
await CloseEntityAsync(logger, item, item.Path).ConfigureAwait(false);
260254
}
261255
}
262256
finally
263257
{
264-
logger.LogDebug(EventIds.MessagingEntityCacheProcessor, "MessagingEntityCache: End-TrimEntries CacheCapacity={CacheCapacity} CacheEntryCount={CacheEntryCount}", Capacity, _entries.Keys.Count);
265-
266258
_semaphore.Release();
267259
}
268260
}

‎src/Helsenorge.Messaging/Amqp/AmqpCore.cs

+10
Original file line numberDiff line numberDiff line change
@@ -282,8 +282,18 @@ private async Task SendAsync(ILogger logger, IAmqpMessage message)
282282

283283
try
284284
{
285+
Stopwatch stopwatch = new Stopwatch();
286+
stopwatch.Start();
287+
288+
logger.LogInformation("Start-CreateCachedMessageSenderAsync");
285289
messageSender = await SenderPool.CreateCachedMessageSenderAsync(logger, message.To).ConfigureAwait(false);
290+
logger.LogInformation($"End-CreateCachedMessageSenderAsync: Execution time: {stopwatch.ElapsedMilliseconds}");
291+
292+
stopwatch.Restart();
293+
294+
logger.LogInformation("Start-MessageSenderSendAsync");
286295
await messageSender.SendAsync(message).ConfigureAwait(false);
296+
logger.LogInformation($"End-MessageSenderSendAsync: Execution time: {stopwatch.ElapsedMilliseconds}");
287297
}
288298
catch (Exception ex)
289299
{

‎src/Helsenorge.Messaging/Amqp/AmqpSender.cs

+1-1
Original file line numberDiff line numberDiff line change
@@ -83,7 +83,7 @@ public async Task SendAsync(IAmqpMessage message, TimeSpan serverWaitTime)
8383
await EnsureOpenAsync().ConfigureAwait(false);
8484
originalMessage.ApplicationProperties.AddApplicationProperties(_applicationProperties);
8585
originalMessage.ApplicationProperties.SetEnqueuedTimeUtc(DateTime.UtcNow);
86-
await _link.SendAsync(originalMessage).ConfigureAwait(false);
86+
await _link.SendAsync(originalMessage, serverWaitTime).ConfigureAwait(false);
8787
}).PerformAsync().ConfigureAwait(false);
8888
}
8989
}

0 commit comments

Comments
 (0)