Skip to content

Commit 85f1ca4

Browse files
brianrobCopilot
andauthored
Optimize nettrace-to-TraceLog Conversion (#2403)
* Use min-heap for EventCache.SortAndDispatch Replace the O(N*T) linear-scan merge in SortAndDispatch with an O(N*log(T)) min-heap merge, where N is the number of events and T is the number of threads. The previous implementation rebuilt a List from LINQ on every call and linearly scanned all thread queues for the minimum timestamp per event. The new implementation uses an array-backed binary min-heap keyed by timestamp. After extracting the minimum, only a single O(log T) sift-down is needed to restore the heap property. The heap list is reused across calls to avoid per-call allocations. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Track active thread queues in EventCache.SortAndDispatch Maintain a HashSet of thread queues that have pending events instead of iterating all threads in the dictionary on every SortAndDispatch call. Queues are added to the active set when their first event is enqueued and removed when drained. This eliminates the Dictionary.Values enumeration which was ~28% of CPU during nettrace-to-TraceLog conversion. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Cache ParsedSymbolMetadata to avoid repeated JSON deserialization Cache the result of ProcessMappingSymbolMetadataParser.TryParse() in ProcessMappingMetadataTraceData so that repeated accesses to the ParsedSymbolMetadata property do not re-invoke JSON deserialization. The property is accessed twice per mapping event (for PE and ELF metadata checks), and the metadata objects are shared across multiple mappings via MetadataId. This was ~10% of CPU during conversion. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Avoid redundant FileName string allocations in ProcessMapping handler Read ProcessMappingTraceData.FileName once into a local variable and pass it directly to UniversalMapping(string, ...) instead of going through the UniversalMapping(ProcessMappingTraceData, ...) overload. Previously, FileName was accessed 3 times per mapping event (IsNullOrEmpty check, StartsWith check, and inside UniversalMapping), each time allocating a new string via GetShortUTF8StringAt(). String allocation was ~12% of CPU in Release-mode profiling. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Reset ParsedSymbolMetadata cache in Dispatch to prevent stale data TraceEvent objects are reused across callbacks. The cached ParsedSymbolMetadata fields were never cleared between dispatches, which could return metadata from a previous event if the property was accessed on the template object rather than a clone. Reset _parsedSymbolMetadataCached and _parsedSymbolMetadata at the start of Dispatch() before invoking the callback. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Address code review feedback: MinHeap class, Clone override, comments Refactor the min-heap helpers into a self-contained private MinHeap class with XML doc comments on all public methods. Add comments explaining the binary heap child index formulas (2i+1, 2i+2). Use C# tuple swap syntax instead of a temp variable. Add Clone() override to ProcessMappingMetadataTraceData to explicitly copy the cached ParsedSymbolMetadata fields into the clone. Strings are immutable so a shallow copy of the reference is sufficient. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> * Add MinHeap unit tests and improve Build() comment Make MinHeap generic (MinHeap<TValue>) and internal so it can be tested from the test project. Add 13 unit tests covering: empty heap, single element, ascending/descending/random input, duplicate keys, ReplaceRoot, RemoveRoot, Clear, and mixed operations. Add a comment to Build() explaining why iteration starts at Count/2-1. Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com> --------- Co-authored-by: Copilot <223556219+Copilot@users.noreply.github.com>
1 parent 696960c commit 85f1ca4

4 files changed

Lines changed: 415 additions & 27 deletions

File tree

src/TraceEvent/EventPipe/EventCache.cs

Lines changed: 158 additions & 24 deletions
Original file line numberDiff line numberDiff line change
@@ -1,7 +1,6 @@
11
using System;
22
using System.Collections.Generic;
33
using System.Diagnostics;
4-
using System.Linq;
54
using System.Runtime.InteropServices;
65

76
namespace Microsoft.Diagnostics.Tracing.EventPipe
@@ -68,6 +67,10 @@ public void ProcessEventBlock(Block block)
6867
}
6968
else
7069
{
70+
if (thread.Events.Count == 0)
71+
{
72+
_activeThreadQueues.Add(thread.Events);
73+
}
7174
thread.Events.Enqueue(eventMarker);
7275
}
7376

@@ -165,49 +168,178 @@ private void CheckForPendingThreadRemoval()
165168

166169
private unsafe void SortAndDispatch(long stopTimestamp)
167170
{
168-
// This sort could be made faster by using a min-heap but this is a simple place to start
169-
List<Queue<EventMarker>> threadQueues = new List<Queue<EventMarker>>(_threads.Values.Select(t => t.Events));
170-
while(true)
171+
// Build a min-heap from active thread queues (those with pending events) whose
172+
// front event is before stopTimestamp. Using _activeThreadQueues avoids iterating
173+
// all threads in the dictionary — only threads that have had events enqueued are checked.
174+
// This gives O(N * log(T)) merge performance where N is the number of events and
175+
// T is the number of active threads.
176+
_heap.Clear();
177+
foreach (Queue<EventMarker> q in _activeThreadQueues)
171178
{
172-
long lowestTimestamp = stopTimestamp;
173-
Queue<EventMarker> oldestEventQueue = null;
174-
foreach(Queue<EventMarker> threadQueue in threadQueues)
179+
if (q.Count > 0)
175180
{
176-
if(threadQueue.Count == 0)
181+
long ts = q.Peek().Header.TimeStamp;
182+
if (ts < stopTimestamp)
177183
{
178-
continue;
184+
_heap.Add(ts, q);
179185
}
180-
long eventTimestamp = threadQueue.Peek().Header.TimeStamp;
181-
if (eventTimestamp < lowestTimestamp)
186+
}
187+
}
188+
189+
if (_heap.Count == 0)
190+
{
191+
return;
192+
}
193+
194+
_heap.Build();
195+
196+
// Merge events in timestamp order using the min-heap.
197+
while (_heap.Count > 0)
198+
{
199+
Queue<EventMarker> minQueue = _heap.PeekValue;
200+
EventMarker eventMarker = minQueue.Dequeue();
201+
OnEvent?.Invoke(ref eventMarker.Header);
202+
203+
if (minQueue.Count > 0)
204+
{
205+
long nextTs = minQueue.Peek().Header.TimeStamp;
206+
if (nextTs < stopTimestamp)
182207
{
183-
oldestEventQueue = threadQueue;
184-
lowestTimestamp = eventTimestamp;
208+
// Update the root with the next timestamp and restore the heap property.
209+
_heap.ReplaceRoot(nextTs, minQueue);
210+
}
211+
else
212+
{
213+
_heap.RemoveRoot();
185214
}
186215
}
187-
if(oldestEventQueue == null)
216+
else
188217
{
189-
break;
218+
_heap.RemoveRoot();
219+
// Remove from active set and free internal storage to prevent unbounded
220+
// memory growth when the application creates and destroys threads.
221+
_activeThreadQueues.Remove(minQueue);
222+
minQueue.TrimExcess();
223+
}
224+
}
225+
}
226+
227+
#region Min-heap Implementation
228+
229+
/// <summary>
230+
/// A min-heap that pairs a long key with a value of type <typeparamref name="TValue"/>.
231+
/// Entries are ordered by key so the minimum key is always at the root.
232+
/// </summary>
233+
internal class MinHeap<TValue>
234+
{
235+
private struct Entry
236+
{
237+
public long Key;
238+
public TValue Value;
239+
240+
public Entry(long key, TValue value)
241+
{
242+
Key = key;
243+
Value = value;
244+
}
245+
}
246+
247+
private readonly List<Entry> _entries = new List<Entry>();
248+
249+
public int Count => _entries.Count;
250+
251+
public TValue PeekValue => _entries[0].Value;
252+
253+
public void Clear() => _entries.Clear();
254+
255+
public void Add(long key, TValue value)
256+
{
257+
_entries.Add(new Entry(key, value));
258+
}
259+
260+
/// <summary>
261+
/// Establishes the heap property over all entries. Call once after adding all
262+
/// entries via Add, before extracting from the heap.
263+
/// </summary>
264+
/// <remarks>
265+
/// Starts from the last non-leaf node (_entries.Count / 2 - 1) and sifts each
266+
/// node down to its correct position. Leaves (the second half of the array) are
267+
/// already trivially valid heaps of size 1, so they are skipped.
268+
/// </remarks>
269+
public void Build()
270+
{
271+
// Start from the last non-leaf node and work backwards to the root.
272+
// Nodes at indices [Count/2 .. Count-1] are leaves that need no adjustment.
273+
for (int i = _entries.Count / 2 - 1; i >= 0; i--)
274+
{
275+
SiftDown(i);
276+
}
277+
}
278+
279+
/// <summary>
280+
/// Replaces the root entry with a new key/value pair and restores the heap property.
281+
/// Use when the root element has been consumed but its source still has more items.
282+
/// </summary>
283+
public void ReplaceRoot(long newKey, TValue value)
284+
{
285+
_entries[0] = new Entry(newKey, value);
286+
SiftDown(0);
287+
}
288+
289+
/// <summary>
290+
/// Removes the root (minimum) entry from the heap and restores the heap property.
291+
/// </summary>
292+
public void RemoveRoot()
293+
{
294+
int lastIndex = _entries.Count - 1;
295+
if (lastIndex == 0)
296+
{
297+
_entries.Clear();
190298
}
191299
else
192300
{
193-
EventMarker eventMarker = oldestEventQueue.Dequeue();
194-
OnEvent?.Invoke(ref eventMarker.Header);
301+
_entries[0] = _entries[lastIndex];
302+
_entries.RemoveAt(lastIndex);
303+
SiftDown(0);
195304
}
196305
}
197306

198-
// If the app creates and destroys threads over time we need to flush old threads
199-
// from the cache or memory usage will grow unbounded. AddThread handles the
200-
// the thread objects but the storage for the queue elements also does not shrink
201-
// below the high water mark unless we free it explicitly.
202-
foreach (Queue<EventMarker> q in threadQueues)
307+
/// <summary>
308+
/// Restores the min-heap property by moving the element at index i down the tree
309+
/// until it is smaller than both children or reaches a leaf position.
310+
/// </summary>
311+
private void SiftDown(int i)
203312
{
204-
if(q.Count == 0)
313+
int count = _entries.Count;
314+
while (true)
205315
{
206-
q.TrimExcess();
316+
int smallest = i;
317+
318+
// In a binary heap stored as an array, the children of node i are at
319+
// indices 2i+1 (left) and 2i+2 (right).
320+
int left = 2 * i + 1;
321+
int right = 2 * i + 2;
322+
323+
if (left < count && _entries[left].Key < _entries[smallest].Key)
324+
{
325+
smallest = left;
326+
}
327+
if (right < count && _entries[right].Key < _entries[smallest].Key)
328+
{
329+
smallest = right;
330+
}
331+
if (smallest == i)
332+
{
333+
break;
334+
}
335+
(_entries[i], _entries[smallest]) = (_entries[smallest], _entries[i]);
336+
i = smallest;
207337
}
208338
}
209339
}
210340

341+
#endregion
342+
211343
private void FreeOldEventBuffers(long stopTimestamp)
212344
{
213345
while (_buffers.Count > 0)
@@ -277,6 +409,8 @@ public EventBlockBuffer(FixedBuffer buffer, long maxTimestamp)
277409
EventPipeEventSource _source;
278410
ThreadCache _threads;
279411
Queue<EventBlockBuffer> _buffers = new Queue<EventBlockBuffer>();
412+
MinHeap<Queue<EventMarker>> _heap = new MinHeap<Queue<EventMarker>>();
413+
HashSet<Queue<EventMarker>> _activeThreadQueues = new HashSet<Queue<EventMarker>>();
280414
}
281415

282416
internal class EventMarker

src/TraceEvent/Parsers/UniversalSystemTraceEventParser.cs

Lines changed: 24 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -355,7 +355,20 @@ public sealed class ProcessMappingMetadataTraceData : TraceEvent
355355

356356
public string SymbolMetadata {get { return GetShortUTF8StringAt(SkipVarInt(0)); } }
357357

358-
internal ProcessMappingSymbolMetadata ParsedSymbolMetadata { get { return ProcessMappingSymbolMetadataParser.TryParse(SymbolMetadata); } }
358+
internal ProcessMappingSymbolMetadata ParsedSymbolMetadata
359+
{
360+
get
361+
{
362+
if (!_parsedSymbolMetadataCached)
363+
{
364+
_parsedSymbolMetadata = ProcessMappingSymbolMetadataParser.TryParse(SymbolMetadata);
365+
_parsedSymbolMetadataCached = true;
366+
}
367+
return _parsedSymbolMetadata;
368+
}
369+
}
370+
private ProcessMappingSymbolMetadata _parsedSymbolMetadata;
371+
private bool _parsedSymbolMetadataCached;
359372

360373
public string VersionMetadata {get {return GetShortUTF8StringAt(SkipShortUTF8String(SkipVarInt(0))); } }
361374

@@ -367,9 +380,19 @@ internal ProcessMappingMetadataTraceData(Action<ProcessMappingMetadataTraceData>
367380
}
368381
protected internal override void Dispatch()
369382
{
383+
_parsedSymbolMetadataCached = false;
384+
_parsedSymbolMetadata = null;
370385
Action(this);
371386
}
372387

388+
public override unsafe TraceEvent Clone()
389+
{
390+
var clone = (ProcessMappingMetadataTraceData)base.Clone();
391+
clone._parsedSymbolMetadata = _parsedSymbolMetadata;
392+
clone._parsedSymbolMetadataCached = _parsedSymbolMetadataCached;
393+
return clone;
394+
}
395+
373396
protected internal override Delegate Target
374397
{
375398
get { return Action; }

src/TraceEvent/SourceConverters/NettraceUniversalConverter.cs

Lines changed: 3 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -62,15 +62,16 @@ public void BeforeProcess(TraceLog traceLog, TraceEventDispatcher source)
6262
}
6363
processes.Add(process);
6464

65-
if (!string.IsNullOrEmpty(data.FileName) && data.FileName.StartsWith(DotnetJittedCodeMappingName, StringComparison.Ordinal))
65+
string fileName = data.FileName;
66+
if (!string.IsNullOrEmpty(fileName) && fileName.StartsWith(DotnetJittedCodeMappingName, StringComparison.Ordinal))
6667
{
6768
// Don't create a module for jitted code.
6869
// These will be created for each jitted code symbol.
6970
return;
7071
}
7172

7273
_mappingMetadata.TryGetValue(data.MetadataId, out ProcessMappingMetadataTraceData metadata);
73-
TraceModuleFile moduleFile = process.LoadedModules.UniversalMapping(data, metadata);
74+
TraceModuleFile moduleFile = process.LoadedModules.UniversalMapping(fileName, data.StartAddress, data.EndAddress, data.TimeStampQPC, metadata);
7475
};
7576
universalSystemParser.ProcessMappingMetadata += delegate (ProcessMappingMetadataTraceData data)
7677
{

0 commit comments

Comments
 (0)