Skip to content

Commit 3140653

Browse files
vaindvaind
committed
tracelog streaming fixes
1 parent a04f1e7 commit 3140653

File tree

2 files changed

+120
-120
lines changed

2 files changed

+120
-120
lines changed

‎src/TraceEvent/TraceEvent.Tests/Parsing/EventPipeParsing.cs

+54-56
Original file line numberDiff line numberDiff line change
@@ -28,11 +28,34 @@ private class EventRecord
2828
public string FirstSeriazliedSample;
2929
}
3030

31+
private class EventStatistics
32+
{
33+
public SortedDictionary<string, EventRecord> Records = new SortedDictionary<string, EventRecord>(StringComparer.Ordinal);
34+
35+
public void Record(TraceEvent data) => Record(data.ProviderName + "/" + data.EventName, data);
36+
37+
public void Record(string eventName, TraceEvent data)
38+
{
39+
if (Records.ContainsKey(eventName))
40+
{
41+
Records[eventName].TotalCount++;
42+
}
43+
else
44+
{
45+
Records[eventName] = new EventRecord()
46+
{
47+
TotalCount = 1,
48+
FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray())
49+
};
50+
}
51+
}
52+
}
53+
3154
public EventPipeParsing(ITestOutputHelper output)
3255
: base(output)
3356
{
3457
}
35-
58+
3659
[Theory()]
3760
[MemberData(nameof(TestEventPipeFiles))]
3861
public void Basic(string eventPipeFileName)
@@ -43,30 +66,13 @@ public void Basic(string eventPipeFileName)
4366
string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName);
4467

4568
Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", Path.GetFullPath(eventPipeFilePath)));
46-
47-
var eventStatistics = new SortedDictionary<string, EventRecord>(StringComparer.Ordinal);
69+
var eventStatistics = new EventStatistics();
4870

4971
using (var traceLog = new TraceLog(TraceLog.CreateFromEventPipeDataFile(eventPipeFilePath)))
5072
{
5173
var traceSource = traceLog.Events.GetSource();
5274

53-
traceSource.AllEvents += delegate (TraceEvent data)
54-
{
55-
string eventName = data.ProviderName + "/" + data.EventName;
56-
57-
if (eventStatistics.ContainsKey(eventName))
58-
{
59-
eventStatistics[eventName].TotalCount++;
60-
}
61-
else
62-
{
63-
eventStatistics[eventName] = new EventRecord()
64-
{
65-
TotalCount = 1,
66-
FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray())
67-
};
68-
}
69-
};
75+
traceSource.AllEvents += eventStatistics.Record;
7076

7177
// Process
7278
traceSource.Process();
@@ -84,7 +90,7 @@ public void Streaming(string eventPipeFileName)
8490

8591
string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName);
8692
Output.WriteLine(string.Format("Processing the file {0}", Path.GetFullPath(eventPipeFilePath)));
87-
var eventStatistics = new SortedDictionary<string, EventRecord>(StringComparer.Ordinal);
93+
var eventStatistics = new EventStatistics();
8894

8995
long curStreamPosition = 0;
9096
using (MockStreamingOnlyStream s = new MockStreamingOnlyStream(new FileStream(eventPipeFilePath, FileMode.Open, FileAccess.Read, FileShare.Read)))
@@ -112,18 +118,7 @@ public void Streaming(string eventPipeFileName)
112118
eventName == "Microsoft-Windows-DotNETRuntime/Method")
113119
return;
114120

115-
if (eventStatistics.ContainsKey(eventName))
116-
{
117-
eventStatistics[eventName].TotalCount++;
118-
}
119-
else
120-
{
121-
eventStatistics[eventName] = new EventRecord()
122-
{
123-
TotalCount = 1,
124-
FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray())
125-
};
126-
}
121+
eventStatistics.Record(eventName, data);
127122
};
128123

129124
// this is somewhat arbitrary looking set of parser event callbacks empirically
@@ -161,33 +156,36 @@ public void TraceLogStreaming(string eventPipeFileName)
161156

162157
string eventPipeFilePath = Path.Combine(UnZippedDataDir, eventPipeFileName);
163158
Output.WriteLine(string.Format("Processing the file {0}", Path.GetFullPath(eventPipeFilePath)));
164-
var eventStatistics = new SortedDictionary<string, EventRecord>(StringComparer.Ordinal);
159+
var eventStatistics = new EventStatistics();
165160

166161
using (MockStreamingOnlyStream s = new MockStreamingOnlyStream(new FileStream(eventPipeFilePath, FileMode.Open, FileAccess.Read, FileShare.Read)))
167162
{
168163
using (var eventPipeSource = new EventPipeEventSource(s))
169164
{
170-
using (var traceSource = TraceLog.CreateFromEventPipeEventSource(eventPipeSource))
165+
using (var traceSource = CreateFromEventPipeEventSource(eventPipeSource))
171166
{
172-
Action<TraceEvent> handler = delegate (TraceEvent data)
173-
{
174-
string eventName = data.ProviderName + "/" + data.EventName;
175-
176-
if (eventStatistics.ContainsKey(eventName))
177-
{
178-
eventStatistics[eventName].TotalCount++;
179-
}
180-
else
181-
{
182-
eventStatistics[eventName] = new EventRecord()
183-
{
184-
TotalCount = 1,
185-
FirstSeriazliedSample = new String(data.ToString().Replace("\n", "\\n").Replace("\r", "\\r").Take(1000).ToArray())
186-
};
187-
}
188-
};
189-
190-
traceSource.AllEvents += handler;
167+
Action<TraceEvent> handler = eventStatistics.Record;
168+
169+
// this is somewhat arbitrary looking set of parser event callbacks empirically
170+
// produces the same set of events as TraceLog.Events.GetSource().AllEvents so
171+
// that the baseline files can be reused from the Basic test
172+
var rundown = new ClrRundownTraceEventParser(traceSource);
173+
rundown.LoaderAppDomainDCStop += handler;
174+
rundown.LoaderAssemblyDCStop += handler;
175+
rundown.LoaderDomainModuleDCStop += handler;
176+
rundown.LoaderModuleDCStop += handler;
177+
rundown.MethodDCStopComplete += handler;
178+
rundown.MethodDCStopInit += handler;
179+
var sampleProfiler = new SampleProfilerTraceEventParser(traceSource);
180+
sampleProfiler.All += handler;
181+
var privateClr = new ClrPrivateTraceEventParser(traceSource);
182+
privateClr.All += handler;
183+
traceSource.Clr.All += handler;
184+
traceSource.Clr.MethodILToNativeMap -= handler;
185+
// traceSource.Dynamic.All += handler;
186+
187+
// TODO Needed for custom events (eventpipe-dotnetcore2.1-linux-x64-tracelogging.net), but the event names are still missing...
188+
// traceSource.UnhandledEvents += handler;
191189

192190
// Process
193191
traceSource.Process();
@@ -620,10 +618,10 @@ private void Dynamic_All(TraceEvent obj)
620618
throw new NotImplementedException();
621619
}
622620

623-
private void ValidateEventStatistics(SortedDictionary<string, EventRecord> eventStatistics, string eventPipeFileName)
621+
private void ValidateEventStatistics(EventStatistics eventStatistics, string eventPipeFileName)
624622
{
625623
StringBuilder sb = new StringBuilder(1024 * 1024);
626-
foreach (var item in eventStatistics)
624+
foreach (var item in eventStatistics.Records)
627625
{
628626
sb.AppendLine($"{item.Key}, {item.Value.TotalCount}, {item.Value.FirstSeriazliedSample}");
629627
}

‎src/TraceEvent/TraceLog.cs

+66-64
Original file line numberDiff line numberDiff line change
@@ -7,7 +7,6 @@
77
using FastSerialization;
88
using Microsoft.Diagnostics.NETCore.Client;
99
using Microsoft.Diagnostics.Symbols;
10-
using Microsoft.Diagnostics.Tracing.Compatibility;
1110
using Microsoft.Diagnostics.Tracing.EventPipe;
1211
using Microsoft.Diagnostics.Tracing.Parsers;
1312
using Microsoft.Diagnostics.Tracing.Parsers.AspNet;
@@ -155,6 +154,7 @@ public static TraceLog OpenOrConvert(string etlOrEtlxFilePath, TraceLogOptions o
155154
public static TraceLogEventSource CreateFromTraceEventSession(TraceEventSession session)
156155
{
157156
var traceLog = new TraceLog(session.Source);
157+
traceLog.pointerSize = ETWTraceEventSource.GetOSPointerSize();
158158

159159
// See if we are on Win7 and have a separate kernel session associated with 'session'
160160
if (session.m_kernelSession != null)
@@ -168,24 +168,32 @@ public static TraceLogEventSource CreateFromTraceEventSession(TraceEventSession
168168
traceLog.rawKernelEventSource = session.m_kernelSession.Source;
169169
traceLog.SetupCallbacks(traceLog.rawKernelEventSource);
170170
traceLog.rawKernelEventSource.unhandledEventTemplate.traceEventSource = traceLog; // Make everything point to the log as its source.
171-
// TODO fixme - onAllEvents is local to the constructor
172-
// traceLog.rawKernelEventSource.AllEvents += traceLog.onAllEvents;
171+
traceLog.rawKernelEventSource.AllEvents += traceLog.onAllEventsRealTime;
173172
}
174173

175174
return traceLog.realTimeSource;
176175
}
177176

177+
/// <summary>
178+
/// From a EventPipeSession, create a real time TraceLog Event Source. Like an EventPipeEventSource a TraceLogEventSource
179+
/// will deliver events in real time. However an TraceLogEventSource has an underlying Tracelog (which you can access with
180+
/// the .Log Property) which lets you get at aggregated information (Processes, threads, images loaded, and perhaps most
181+
/// importantly TraceEvent.CallStack() will work. Thus you can get real time stacks from events).
182+
/// </summary>
178183
public static TraceLogEventSource CreateFromEventPipeSession(EventPipeSession session)
179184
{
180185
return CreateFromEventPipeEventSource(new EventPipeEventSource(session.EventStream));
181186
}
182187

188+
/// <summary>
189+
/// From a EventPipeEventSource, create a real time TraceLog Event Source. Like an EventPipeEventSource a TraceLogEventSource
190+
/// will deliver events in real time. However an TraceLogEventSource has an underlying Tracelog (which you can access with
191+
/// the .Log Property) which lets you get at aggregated information (Processes, threads, images loaded, and perhaps most
192+
/// importantly TraceEvent.CallStack() will work. Thus you can get real time stacks from events).
193+
/// </summary>
183194
public static TraceLogEventSource CreateFromEventPipeEventSource(EventPipeEventSource source)
184195
{
185196
var traceLog = new TraceLog(source);
186-
var dynamicParser = source.Dynamic;
187-
var clrParser = source.Clr;
188-
var kernelParser = source.Kernel;
189197
return traceLog.realTimeSource;
190198
}
191199

@@ -583,65 +591,63 @@ private unsafe TraceLog(TraceEventDispatcher source)
583591

584592
realTimeSource = new TraceLogEventSource(events, ownsItsTraceLog: true); // Dispose
585593
realTimeQueue = new Queue<QueueEntry>();
586-
realTimeFlushTimer = new Timer(FlushRealTimeEvents, null, 1000, 1000);
587-
pointerSize = ETWTraceEventSource.GetOSPointerSize();
594+
realTimeFlushTimer = new Timer(_ => FlushRealTimeEvents(1000), null, 1000, 1000);
588595

589596
//double lastTime = 0;
590597

591-
// Set up callbacks that handle stack processing
592-
Action<TraceEvent> onAllEvents = delegate (TraceEvent data)
593-
{
594-
// we need to guard our data structures from concurrent access. TraceLog data
595-
// is modified by this code as well as code in FlushRealTimeEvents.
596-
lock (realTimeQueue)
597-
{
598-
// we delay things so we have a chance to match up stacks.
599-
600-
// if (!removeFromStream && data.Opcode != TraceEventOpcode.DataCollectionStart && data.ProcessID != 0 && data.ProviderGuid != ClrRundownTraceEventParser.ProviderGuid)
601-
// Trace.WriteLine("REAL TIME QUEUE: " + data.ToString());
602-
TraceEventCounts countForEvent = Stats.GetEventCounts(data);
603-
Debug.Assert((int)data.EventIndex == eventCount);
604-
countForEvent.m_count++;
605-
countForEvent.m_eventDataLenTotal += data.EventDataLength;
598+
// Set up callbacks - we use the session's source for our input.
599+
rawEventSourceToConvert = source;
600+
SetupCallbacks(rawEventSourceToConvert);
601+
rawEventSourceToConvert.unhandledEventTemplate.traceEventSource = this; // Make everything point to the log as its source.
602+
rawEventSourceToConvert.AllEvents += onAllEventsRealTime;
603+
}
606604

607-
// Remember past events so we can hook up stacks to them.
608-
data.eventIndex = (EventIndex)eventCount;
609-
pastEventInfo.LogEvent(data, data.eventIndex, countForEvent);
605+
private unsafe void onAllEventsRealTime(TraceEvent data)
606+
{
607+
// we need to guard our data structures from concurrent access. TraceLog data
608+
// is modified by this code as well as code in FlushRealTimeEvents.
609+
lock (realTimeQueue)
610+
{
611+
// we delay things so we have a chance to match up stacks.
610612

611-
// currentID is used by the dispatcher to define the EventIndex. Make sure at both sources have the
612-
// same notion of what that is if we have two dispatcher.
613-
if (rawKernelEventSource != null)
614-
{
615-
rawEventSourceToConvert.currentID = (EventIndex)eventCount;
616-
rawKernelEventSource.currentID = (EventIndex)eventCount;
617-
}
613+
// if (!removeFromStream && data.Opcode != TraceEventOpcode.DataCollectionStart && data.ProcessID != 0 && data.ProviderGuid != ClrRundownTraceEventParser.ProviderGuid)
614+
// Trace.WriteLine("REAL TIME QUEUE: " + data.ToString());
615+
TraceEventCounts countForEvent = Stats.GetEventCounts(data);
616+
Debug.Assert((int)data.EventIndex == eventCount);
617+
countForEvent.m_count++;
618+
countForEvent.m_eventDataLenTotal += data.EventDataLength;
618619

619-
// Skip samples from the idle thread.
620-
if (data.ProcessID == 0 && data is SampledProfileTraceData)
621-
{
622-
return;
623-
}
620+
// Remember past events so we can hook up stacks to them.
621+
data.eventIndex = (EventIndex)eventCount;
622+
pastEventInfo.LogEvent(data, data.eventIndex, countForEvent);
624623

625-
var extendedDataCount = data.eventRecord->ExtendedDataCount;
626-
if (extendedDataCount != 0)
627-
{
628-
bookKeepingEvent |= ProcessExtendedData(data, extendedDataCount, countForEvent);
629-
}
624+
// currentID is used by the dispatcher to define the EventIndex. Make sure at both sources have the
625+
// same notion of what that is if we have two dispatcher.
626+
if (rawKernelEventSource != null)
627+
{
628+
rawEventSourceToConvert.currentID = (EventIndex)eventCount;
629+
rawKernelEventSource.currentID = (EventIndex)eventCount;
630+
}
630631

631-
// This must occur after the call to ProcessExtendedData to ensure that if there is a stack for this event,
632-
// that it has been associated before the event count is incremented. Otherwise, the stack will be associated with
633-
// the next event, and not the current event.
634-
eventCount++;
632+
// Skip samples from the idle thread.
633+
if (data.ProcessID == 0 && data is SampledProfileTraceData)
634+
{
635+
return;
636+
}
635637

636-
realTimeQueue.Enqueue(new QueueEntry(data.Clone(), Environment.TickCount));
638+
var extendedDataCount = data.eventRecord->ExtendedDataCount;
639+
if (extendedDataCount != 0)
640+
{
641+
bookKeepingEvent |= ProcessExtendedData(data, extendedDataCount, countForEvent);
637642
}
638-
};
639643

640-
// We use the session's source for our input.
641-
rawEventSourceToConvert = source;
642-
SetupCallbacks(rawEventSourceToConvert);
643-
rawEventSourceToConvert.unhandledEventTemplate.traceEventSource = this; // Make everything point to the log as its source.
644-
rawEventSourceToConvert.AllEvents += onAllEvents;
644+
// This must occur after the call to ProcessExtendedData to ensure that if there is a stack for this event,
645+
// that it has been associated before the event count is incremented. Otherwise, the stack will be associated with
646+
// the next event, and not the current event.
647+
eventCount++;
648+
649+
realTimeQueue.Enqueue(new QueueEntry(data.Clone(), Environment.TickCount));
650+
}
645651
}
646652

647653
/// <summary>
@@ -672,25 +678,19 @@ private unsafe void DispatchClonedEvent(TraceEvent toSend)
672678
}
673679

674680
/// <summary>
675-
/// Flushes any event that has waited around long enough
681+
/// Flushes any event that has waited around for longer than minimumAgeMs.
676682
/// </summary>
677-
private void FlushRealTimeEvents(object notUsed)
683+
internal void FlushRealTimeEvents(int minimumAgeMs = 0)
678684
{
679685
lock (realTimeQueue)
680686
{
681687
var nowTicks = Environment.TickCount;
682688
// TODO review.
683-
for (; ; )
689+
while (realTimeQueue.Count > 0)
684690
{
685-
var count = realTimeQueue.Count;
686-
if (count == 0)
687-
{
688-
break;
689-
}
690-
691691
QueueEntry entry = realTimeQueue.Peek();
692692
// If it has been in the queue less than 1 second, we we wait until next time) & 3FFFFFF does wrap around subtraction.
693-
if (((nowTicks - entry.enqueueTick) & 0x3FFFFFFF) < 1000)
693+
if (minimumAgeMs > 0 && ((nowTicks - entry.enqueueTick) & 0x3FFFFFFF) < minimumAgeMs)
694694
{
695695
break;
696696
}
@@ -4323,6 +4323,8 @@ public override bool Process()
43234323
TraceLog.rawKernelEventSource.StopProcessing();
43244324
kernelTask.Wait();
43254325
}
4326+
// Flush all outstanding events in the realTimeQueue.
4327+
TraceLog.FlushRealTimeEvents();
43264328
return true;
43274329
}
43284330
Debug.Assert(unhandledEventTemplate.traceEventSource == TraceLog);

0 commit comments

Comments
 (0)