public void Basic(string bperfFileName)
{
// Initialize
PrepareTestData();
Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", Path.GetFullPath(bperfFileName)));
var sb = new StringBuilder(1024 * 1024);
var traceEventDispatcherOptions = new TraceEventDispatcherOptions();
Guid systemTrace = new Guid("9e814aad-3204-11d2-9a82-006008a86939");
using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(Path.GetFullPath(bperfFileName), traceEventDispatcherOptions: traceEventDispatcherOptions)))
{
var traceSource = traceLog.Events.GetSource();
traceSource.AllEvents += delegate(TraceEvent data)
{
if (data.ProviderGuid != systemTrace || (int)data.Opcode != 80)
{
sb.AppendLine(Parse(data));
}
};
// Process
traceSource.Process();
}
// Validate
ValidateEventStatistics(sb.ToString(0, 1024 * 1024), Path.GetFileNameWithoutExtension(bperfFileName));
}
public void Basic(string bperfFileName)
{
// Initialize
PrepareTestData();
Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", Path.GetFullPath(bperfFileName)));
var sb = new StringBuilder(1024 * 1024);
var traceEventDispatcherOptions = new TraceEventDispatcherOptions();
using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(Path.GetFullPath(bperfFileName), traceEventDispatcherOptions: traceEventDispatcherOptions)))
{
var traceSource = traceLog.Events.GetSource();
traceSource.AllEvents += delegate(TraceEvent data)
{
sb.AppendLine(Parse(data));
};
// Process
traceSource.Process();
}
// Validate
ValidateEventStatistics(sb.ToString(0, 1024 * 1024), Path.GetFileNameWithoutExtension(bperfFileName));
}
public TraceLogDeserializer(string etlFileNameWithTimeStamps)
{
var endTimeStart = etlFileNameWithTimeStamps.LastIndexOf('*');
var e = etlFileNameWithTimeStamps.Substring(endTimeStart + 1, etlFileNameWithTimeStamps.Length - (endTimeStart + 1));
var startTimeStart = etlFileNameWithTimeStamps.LastIndexOf('*', endTimeStart - 1);
var s = etlFileNameWithTimeStamps.Substring(startTimeStart + 1, endTimeStart - (startTimeStart + 1));
var etlFileName = etlFileNameWithTimeStamps.Substring(0, startTimeStart);
if (!DateTime.TryParse(s, out var startTime))
{
startTime = DateTime.MinValue;
}
if (!DateTime.TryParse(e, out var endTime))
{
endTime = DateTime.MaxValue;
}
var etlxPath = etlFileName + "." + startTime.ToString("yyyyddMHHmmss") + "-" + endTime.ToString("yyyyddMHHmmss") + ".etlx";
if (!File.Exists(etlxPath))
{
var tmp = etlxPath + ".new";
try
{
TraceLog.CreateFromEventTraceLogFile(etlFileName, tmp, new TraceLogOptions {
MaxEventCount = int.MaxValue, KeepAllEvents = true
}, new TraceEventDispatcherOptions {
StartTime = startTime, EndTime = endTime
});
File.Move(tmp, etlxPath);
}
finally
{
if (File.Exists(tmp))
{
File.Delete(tmp);
}
}
}
this.traceLog = new TraceLog(etlxPath);
this.EventStats = new Dictionary <int, TraceEventCounts>(this.traceLog.Stats.Count);
this.TraceProcesses = this.traceLog.Processes;
this.TraceModuleFiles = this.traceLog.ModuleFiles;
this.TraceInfo = new TraceInfo(this.traceLog.MachineName, this.traceLog.OSName, this.traceLog.OSBuild, this.traceLog.UTCOffsetMinutes, TimeZoneInfo.Local.BaseUtcOffset, this.traceLog.BootTime, this.traceLog.SessionStartTime, this.traceLog.SessionEndTime, this.traceLog.SessionEndTimeRelativeMSec, this.traceLog.SessionDuration, this.traceLog.CpuSpeedMHz, this.traceLog.NumberOfProcessors, this.traceLog.MemorySizeMeg, this.traceLog.PointerSize, this.traceLog.SampleProfileInterval, this.traceLog.EventCount, this.traceLog.EventsLost, this.traceLog.Size);
int i = 1;
this.internalEventMapping.Add(new EtwProviderInfo(new Guid("{9e814aad-3204-11d2-9a82-006008a86939}"), 0), 0); // for EventTrace Header
foreach (var eventStat in this.traceLog.Stats)
{
this.EventStats.Add(i, eventStat);
this.internalEventMapping.Add(new EtwProviderInfo(eventStat.IsClassic ? eventStat.TaskGuid : eventStat.ProviderGuid, eventStat.IsClassic ? (int)eventStat.Opcode : (int)eventStat.EventID), i);
this.TotalStackCount += eventStat.StackCount;
this.TotalEventCount += eventStat.Count;
i++;
}
}
public static IEnumerable <Metric> Parse(string etlFilePath, PreciseMachineCounter[] counters)
{
using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath)))
{
var traceLogEventSource = traceLog.Events.GetSource();
return(new TraceLogParser().Parse(traceLogEventSource, counters));
}
}
public IEnumerable <Metric> Parse()
{
var etlxFilePath = TraceLog.CreateFromEventTraceLogFile(etlFilePath);
try
{
using (var traceLog = new TraceLog(etlxFilePath))
{
return(Parse(traceLog));
}
}
finally
{
etlxFilePath.DeleteFileIfExists();
}
}
public TraceLogDeserializer(string etlFileName)
{
this.traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFileName));
this.EventStats = new Dictionary <int, TraceEventCounts>(this.traceLog.Stats.Count);
this.TraceProcesses = this.traceLog.Processes;
int i = 1;
this.internalEventMapping.Add(new EtwProviderInfo(new Guid("{9e814aad-3204-11d2-9a82-006008a86939}"), 0), 0); // for EventTrace Header
foreach (var eventStat in this.traceLog.Stats)
{
this.EventStats.Add(i, eventStat);
this.internalEventMapping.Add(new EtwProviderInfo(eventStat.IsClassic ? eventStat.TaskGuid : eventStat.ProviderGuid, eventStat.IsClassic ? (int)eventStat.Opcode : (int)eventStat.EventID), i);
this.TotalStackCount += eventStat.StackCount;
this.TotalEventCount += eventStat.Count;
i++;
}
}
public static IEnumerable <Metric> Parse(string etlFilePath, PreciseMachineCounter[] counters)
{
var etlxFilePath = TraceLog.CreateFromEventTraceLogFile(etlFilePath);
try
{
using (var traceLog = new TraceLog(etlxFilePath))
{
var traceLogEventSource = traceLog.Events.GetSource();
return(new TraceLogParser().Parse(traceLogEventSource, counters));
}
}
finally
{
etlxFilePath.DeleteFileIfExists();
}
}
public void ETW_GeneralParsing_Basic(string etlFileName)
{
Output.WriteLine($"In {nameof(ETW_GeneralParsing_Basic)}(\"{etlFileName}\")");
PrepareTestData();
string etlFilePath = Path.Combine(UnZippedDataDir, etlFileName);
bool anyFailure = false;
Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", Path.GetFullPath(etlFilePath)));
string eltxFilePath = Path.ChangeExtension(etlFilePath, ".etlx");
// See if we have a cooresponding baseline file
string baselineName = Path.Combine(Path.GetFullPath(TestDataDir),
Path.GetFileNameWithoutExtension(etlFilePath) + ".baseline.txt");
string newBaselineName = Path.Combine(NewBaselineDir,
Path.GetFileNameWithoutExtension(etlFilePath) + ".baseline.txt");
string outputName = Path.Combine(OutputDir,
Path.GetFileNameWithoutExtension(etlFilePath) + ".txt");
TextWriter outputFile = File.CreateText(outputName);
StreamReader baselineFile = null;
if (File.Exists(baselineName))
{
baselineFile = File.OpenText(baselineName);
}
else
{
Output.WriteLine("WARNING: No baseline file");
Output.WriteLine(string.Format(" ETL FILE: {0}", Path.GetFullPath(etlFilePath)));
Output.WriteLine(string.Format(" NonExistant Baseline File: {0}", baselineName));
Output.WriteLine("To Create a baseline file");
Output.WriteLine(string.Format(" copy /y \"{0}\" \"{1}\"",
Path.GetFullPath(newBaselineName),
Path.GetFullPath(baselineName)
));
}
bool unexpectedUnknownEvent = false;
int firstFailLineNum = 0;
int mismatchCount = 0;
int lineNum = 0;
var histogram = new SortedDictionary <string, int>(StringComparer.Ordinal);
// TraceLog traceLog = TraceLog.OpenOrConvert(etlFilePath); // This one can be used during development of test itself
TraceLog traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath));
var traceSource = traceLog.Events.GetSource();
traceSource.AllEvents += delegate(TraceEvent data)
{
string eventName = data.ProviderName + "/" + data.EventName;
// We are going to skip dynamic events from the CLR provider.
// The issue is that this depends on exactly which manifest is present
// on the machine, and I just don't want to deal with the noise of
// failures because you have a slightly different one.
if (data.ProviderName == "DotNet")
{
return;
}
// We don't want to use the manifest for CLR Private events since
// different machines might have different manifests.
if (data.ProviderName == "Microsoft-Windows-DotNETRuntimePrivate")
{
if (data.GetType().Name == "DynamicTraceEventData" || data.EventName.StartsWith("EventID"))
{
return;
}
}
// Same problem with classic OS events. We don't want to rely on the OS to parse since this could vary between baseline and test.
else if (data.ProviderName == "MSNT_SystemTrace")
{
// However we to allow a couple of 'known good' ones through so we test some aspects of the OS parsing logic in TraceEvent.
if (data.EventName != "SystemConfig/Platform" && data.EventName != "Image/KernelBase")
{
return;
}
}
// In theory we have the same problem with any event that the OS supplies the parsing. I dont want to be too aggressive about
// turning them off, however becasuse I want those code paths tested
// TODO FIX NOW, this is broken and should be fixed.
// We are hacking it here so we don't turn off the test completely.
if (eventName == "DotNet/CLR.SKUOrVersion")
{
return;
}
int count = IncCount(histogram, eventName);
// To keep the baseline size under control, we only check at
// most 5 of each event type.
const int MaxEventPerType = 5;
if (count > MaxEventPerType)
{
return;
}
string parsedEvent = Parse(data);
lineNum++;
outputFile.WriteLine(parsedEvent); // Make the new output file.
string expectedParsedEvent = null;
if (baselineFile != null)
{
expectedParsedEvent = baselineFile.ReadLine();
}
if (expectedParsedEvent == null)
{
expectedParsedEvent = "";
}
// If we have baseline, it should match what we have in the file.
if (baselineFile != null && parsedEvent != expectedParsedEvent)
{
mismatchCount++;
if (firstFailLineNum == 0)
{
firstFailLineNum = lineNum;
anyFailure = true;
Output.WriteLine(string.Format("ERROR: File {0}: event not equal to expected on line {1}", etlFilePath, lineNum));
Output.WriteLine(string.Format(" Expected: {0}", expectedParsedEvent));
Output.WriteLine(string.Format(" Actual : {0}", parsedEvent));
Output.WriteLine("To Compare output and baseline (baseline is SECOND)");
Output.WriteLine(string.Format(" windiff \"{0}\" \"{1}\"",
Path.GetFullPath(newBaselineName),
Path.GetFullPath(baselineName)
));
}
}
// Even if we don't have a baseline, we can check that the event names are OK.
if (0 <= eventName.IndexOf('(')) // Unknown events have () in them
{
// Some expected events we don't handle today.
if (data.EventName != "EventID(65534)" && // Manifest events
data.ProviderName != "Microsoft-Windows-DNS-Client" &&
eventName != "KernelTraceControl/ImageID/Opcode(34)" &&
eventName != "Windows Kernel/DiskIO/Opcode(16)" &&
eventName != "Windows Kernel/SysConfig/Opcode(37)")
{
Output.WriteLine(string.Format("ERROR: File {0}: has unknown event {1} at {2:n3} MSec",
etlFilePath, eventName, data.TimeStampRelativeMSec));
// Assert throws an exception which gets swallowed in Process() so instead
// we remember that we failed and assert outside th callback.
unexpectedUnknownEvent = true;
}
}
};
/********************* PROCESSING ***************************/
traceSource.Process();
// Validation after processing, first we check that the histograms are the same as the baseline
// We also want to check that the count of events is the same as the baseline.
bool histogramMismatch = false;
foreach (var keyValue in histogram)
{
var histogramLine = "COUNT " + keyValue.Key + ":" + keyValue.Value;
outputFile.WriteLine(histogramLine);
var expectedistogramLine = baselineFile.ReadLine();
lineNum++;
if (!histogramMismatch && expectedistogramLine != histogramLine)
{
histogramMismatch = true;
Output.WriteLine(string.Format("ERROR: File {0}: histogram not equal on {1}", etlFilePath, lineNum));
Output.WriteLine(string.Format(" Expected: {0}", histogramLine));
Output.WriteLine(string.Format(" Actual : {0}", expectedistogramLine));
Output.WriteLine("To Compare output and baseline (baseline is SECOND)");
Output.WriteLine(string.Format(" windiff \"{0}\" \"{1}\"",
Path.GetFullPath(newBaselineName),
Path.GetFullPath(baselineName)
));
anyFailure = true;
}
}
outputFile.Close();
if (mismatchCount > 0)
{
Output.WriteLine(string.Format("ERROR: File {0}: had {1} mismatches", etlFilePath, mismatchCount));
if (!Directory.Exists(NewBaselineDir))
{
Directory.CreateDirectory(NewBaselineDir);
}
File.Copy(outputName, newBaselineName, true);
Output.WriteLine(string.Format("To Update: xcopy /s \"{0}\" \"{1}\"",
Path.GetFullPath(NewBaselineDir), OriginalBaselineDir));
}
// If this fires, check the output for the TraceLine just before it for more details.
Assert.False(unexpectedUnknownEvent, "Check trace output for details. Search for ERROR");
Assert.True(lineNum > 0); // We had some events.
Assert.False(anyFailure, "Check trace output for details. Search for ERROR");
}
//Code is inspired by https://github.com/Microsoft/perfview/blob/master/src/PerfView/PerfViewData.cs#L5719-L5944
public IEnumerable <Metric> Parse()
{
using (var traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath)))
{
var eventSource = traceLog.Events.GetSource();
var bdnEventsParser = new EngineEventLogParser(eventSource);
var start = false;
var isFirstActualStartEnd = false;
long totalOperation = 0;
long countOfAllocatedObject = 0;
bdnEventsParser.WorkloadActualStart += data =>
{
if (!isFirstActualStartEnd)
{
start = true;
}
totalOperation = data.TotalOperations;
};
bdnEventsParser.WorkloadActualStop += data =>
{
start = false;
isFirstActualStartEnd = true;
};
var heapParser = new HeapTraceProviderTraceEventParser(eventSource);
// We index by heap address and then within the heap we remember the allocation stack
var heaps = new Dictionary <Address, Dictionary <Address, long> >();
Dictionary <Address, long> lastHeapAllocs = null;
Address lastHeapHandle = 0;
long nativeLeakSize = 0;
long totalAllocation = 0;
heapParser.HeapTraceAlloc += delegate(HeapAllocTraceData data)
{
if (!start)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
allocs[data.AllocAddress] = data.AllocSize;
checked
{
countOfAllocatedObject++;
nativeLeakSize += data.AllocSize;
totalAllocation += data.AllocSize;
}
};
heapParser.HeapTraceFree += delegate(HeapFreeTraceData data)
{
if (!start)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
if (allocs.TryGetValue(data.FreeAddress, out long alloc))
{
nativeLeakSize -= alloc;
allocs.Remove(data.FreeAddress);
}
};
heapParser.HeapTraceReAlloc += delegate(HeapReallocTraceData data)
{
if (!start)
{
return;
}
// Reallocs that actually move stuff will cause a Alloc and delete event
// so there is nothing to do for those events. But when the address is
// the same we need to resize.
if (data.OldAllocAddress != data.NewAllocAddress)
{
return;
}
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
// This is a clone of the Free code
if (allocs.TryGetValue(data.OldAllocAddress, out long alloc))
{
nativeLeakSize -= alloc;
allocs.Remove(data.OldAllocAddress);
}
// This is a clone of the Alloc code (sigh don't clone code)
allocs[data.NewAllocAddress] = data.NewAllocSize;
checked
{
nativeLeakSize += data.NewAllocSize;
}
};
heapParser.HeapTraceDestroy += delegate(HeapTraceData data)
{
if (!start)
{
return;
}
// Heap is dieing, kill all objects in it.
var allocs = lastHeapAllocs;
if (data.HeapHandle != lastHeapHandle)
{
allocs = CreateHeapCache(data.HeapHandle, heaps, ref lastHeapAllocs, ref lastHeapHandle);
}
foreach (var alloc in allocs.Values)
{
nativeLeakSize -= alloc;
}
};
eventSource.Process();
logger.WriteLine();
logger.WriteLineHeader(LogSeparator);
logger.WriteLineInfo($"{benchmarkCase.DisplayInfo}");
logger.WriteLineHeader(LogSeparator);
if (totalOperation == 0)
{
logger.WriteLine($"Something went wrong. The trace file {etlFilePath} does not contain BenchmarkDotNet engine events.");
yield break;
}
var memoryAllocatedPerOperation = totalAllocation / totalOperation;
var memoryLeakPerOperation = nativeLeakSize / totalOperation;
logger.WriteLine($"Native memory allocated per single operation: {SizeValue.FromBytes(memoryAllocatedPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
logger.WriteLine($"Count of allocated object: {countOfAllocatedObject / totalOperation}");
if (nativeLeakSize != 0)
{
logger.WriteLine($"Native memory leak per single operation: {SizeValue.FromBytes(memoryLeakPerOperation).ToString(SizeUnit.B, benchmarkCase.Config.CultureInfo)}");
}
var heapInfoList = heaps.Select(h => new { Address = h.Key, h.Value.Count, types = h.Value.Values });
foreach (var item in heapInfoList.Where(p => p.Count > 0))
{
logger.WriteLine($"Count of not deallocated object: {item.Count / totalOperation}");
}
yield return(new Metric(new AllocatedNativeMemoryDescriptor(), memoryAllocatedPerOperation));
yield return(new Metric(new NativeMemoryLeakDescriptor(), memoryLeakPerOperation));
}
}
public ICallTreeDataProvider Get()
{
var queryString = this.httpRequest.Query;
string filename = queryString["filename"];
string stacktype = queryString["stacktype"];
if (string.IsNullOrEmpty(filename))
{
throw new ArgumentNullException("filename");
}
if (string.IsNullOrEmpty(stacktype))
{
throw new ArgumentNullException("stacktype");
}
/* symbols and sources related parameters */
string sympath = queryString["sympath"];
string srcpath = queryString["srcpath"];
string imageFilter = queryString["imagefilter"];
string modulesFilter = queryString["modulesfilter"];
/* filtering parameters */
string start = queryString["start"];
string end = queryString["end"];
string incpats = queryString["incpats"];
string excpats = queryString["excpats"];
string foldpats = queryString["foldpats"];
string grouppats = queryString["grouppats"];
string foldpct = queryString["foldpct"];
EtlxFile etlxFile;
string etlxFilePath = Path.Combine(tempPath, Path.ChangeExtension(filename.Replace(@"\", "_"), etlxExtension));
SymbolReader symbolReader;
lock (this.etlxCache)
{
if (this.etlxCache.TryGetValue(filename, out etlxFile))
{
if (etlxFile == null)
{
throw new ArgumentNullException("etlxFile");
}
}
else
{
etlxFile = new EtlxFile(filename)
{
Pending = true
};
this.etlxCache.Set(filename, etlxFile, this.cacheExpirationTime);
}
}
lock (etlxFile)
{
if (etlxFile.Pending)
{
if (!File.Exists(etlxFilePath))
{
// if it's a zip file
if (string.Equals(Path.GetExtension(filename), ".vspx", StringComparison.OrdinalIgnoreCase))
{
using (ZipArchive archive = ZipFile.OpenRead(filename))
{
foreach (ZipArchiveEntry entry in archive.Entries)
{
if (entry.FullName.EndsWith(etlExtension, StringComparison.OrdinalIgnoreCase))
{
entry.ExtractToFile(Path.ChangeExtension(etlxFilePath, etlExtension));
break;
}
}
}
TraceLog.CreateFromEventTraceLogFile(Path.ChangeExtension(etlxFilePath, etlExtension), etlxFilePath);
}
else
{
TraceLog.CreateFromEventTraceLogFile(filename, etlxFilePath);
}
}
etlxFile.TraceLog = TraceLog.OpenOrConvert(etlxFilePath);
etlxFile.Pending = false;
var processes = etlxFile.TraceLog.Processes;
symbolReader = new SymbolReader(this.textWriter, sympath)
{
SourcePath = srcpath
};
foreach (var process in processes)
{
if (string.IsNullOrEmpty(imageFilter) || string.Equals(process.ImageFileName, imageFilter, StringComparison.OrdinalIgnoreCase))
{
foreach (var module in process.LoadedModules)
{
if (string.IsNullOrEmpty(modulesFilter) || modulesFilter.Split(',').Contains(module.Name))
{
etlxFile.TraceLog.CodeAddresses.LookupSymbolsForModule(symbolReader, module.ModuleFile);
}
}
}
}
}
}
StackViewerSession stackViewerSession;
lock (this.stackViewerSessionCache)
{
var filterParams = new FilterParams {
Name = filename + stacktype, StartTimeRelativeMSec = start, EndTimeRelativeMSec = end, MinInclusiveTimePercent = foldpct, FoldRegExs = foldpats, IncludeRegExs = incpats, ExcludeRegExs = excpats, GroupRegExs = grouppats
};
var stackViewerKey = filterParams.ToString();
if (this.stackViewerSessionCache.TryGetValue(stackViewerKey, out stackViewerSession))
{
if (stackViewerSession == null)
{
throw new ArgumentNullException("stackViewerSession");
}
}
else
{
var processes = etlxFile.TraceLog.Processes;
symbolReader = new SymbolReader(this.textWriter, sympath)
{
SourcePath = srcpath
};
foreach (var process in processes)
{
if (string.IsNullOrEmpty(imageFilter) || string.Equals(process.ImageFileName, imageFilter, StringComparison.OrdinalIgnoreCase))
{
foreach (var module in process.LoadedModules)
{
if (string.IsNullOrEmpty(modulesFilter) || modulesFilter.Split(',').Contains(module.Name))
{
etlxFile.TraceLog.CodeAddresses.LookupSymbolsForModule(symbolReader, module.ModuleFile);
}
}
}
}
stackViewerSession = new StackViewerSession(filename, stacktype, etlxFile.TraceLog, filterParams, symbolReader);
this.stackViewerSessionCache.Set(stackViewerKey, stackViewerSession, cacheExpirationTime);
}
}
lock (stackViewerSession)
{
if (stackViewerSession.Pending)
{
stackViewerSession.InitializeDataProvider();
stackViewerSession.Pending = false;
}
}
return(stackViewerSession.GetDataProvider());
}
public void ETW_GeneralParsing_Basic()
{
if (Directory.Exists(OutputDir))
{
Directory.Delete(OutputDir, true);
}
Directory.CreateDirectory(OutputDir);
bool anyFailure = false;
foreach (var etlFilePath in Directory.EnumerateFiles(UnZippedDataDir, "*.etl"))
{
// *.etl includes *.etlx (don't know why), filter those out.
if (!etlFilePath.EndsWith("etl", StringComparison.OrdinalIgnoreCase))
{
continue;
}
Trace.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", etlFilePath));
string eltxFilePath = Path.ChangeExtension(etlFilePath, ".etlx");
// See if we have a cooresponding baseline file
string baselineName = Path.Combine(Path.GetFullPath(TestDataDir),
Path.GetFileNameWithoutExtension(etlFilePath) + ".baseline.txt");
string outputName = Path.Combine(OutputDir,
Path.GetFileNameWithoutExtension(etlFilePath) + ".txt");
TextWriter outputFile = File.CreateText(outputName);
StreamReader baselineFile = null;
if (File.Exists(baselineName))
{
baselineFile = File.OpenText(baselineName);
}
else
{
Trace.WriteLine("WARNING: No baseline file");
Trace.WriteLine(string.Format(" ETL FILE: {0}", Path.GetFullPath(etlFilePath)));
Trace.WriteLine(string.Format(" NonExistant Baseline File: {0}", baselineName));
Trace.WriteLine("To Create a baseline file");
Trace.WriteLine(string.Format(" copy /y \"{0}\" \"{1}\"",
Path.GetFullPath(outputName),
Path.GetFullPath(baselineName)
));
}
bool unexpectedUnknownEvent = false;
int firstFailLineNum = 0;
int mismatchCount = 0;
int lineNum = 0;
var histogram = new SortedDictionary <string, int>();
// TraceLog traceLog = TraceLog.OpenOrConvert(etlFilePath); // This one can be used during developent of test itself
TraceLog traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(etlFilePath));
var traceSource = traceLog.Events.GetSource();
traceSource.AllEvents += delegate(TraceEvent data)
{
string eventName = data.ProviderName + "/" + data.EventName;
int count = IncCount(histogram, eventName);
// To keep the baseline size under control, we only check at
// most 5 of each event type.
const int MaxEventPerType = 5;
if (count > MaxEventPerType)
{
return;
}
// TODO FIX NOW, this is broken and should be fixed.
// We are hacking it here so we don't turn off the test completely.
if (eventName == "DotNet/CLR.SKUOrVersion")
{
return;
}
string parsedEvent = Parse(data);
lineNum++;
outputFile.WriteLine(parsedEvent); // Make the new output file.
string expectedParsedEvent = null;
if (baselineFile != null)
{
expectedParsedEvent = baselineFile.ReadLine();
}
if (expectedParsedEvent == null)
{
expectedParsedEvent = "";
}
// If we have baseline, it should match what we have in the file.
if (baselineFile != null && parsedEvent != expectedParsedEvent)
{
mismatchCount++;
if (firstFailLineNum == 0)
{
firstFailLineNum = lineNum;
anyFailure = true;
Trace.WriteLine(string.Format("ERROR: File {0}: event not equal to expected on line {1}", etlFilePath, lineNum));
Trace.WriteLine(string.Format(" Expected: {0}", expectedParsedEvent));
Trace.WriteLine(string.Format(" Actual : {0}", parsedEvent));
Trace.WriteLine("To Compare output and baseline (baseline is SECOND)");
Trace.WriteLine(string.Format(" windiff \"{0}\" \"{1}\"",
Path.GetFullPath(outputName),
Path.GetFullPath(baselineName)
));
Trace.WriteLine("To Update baseline file");
Trace.WriteLine(string.Format(" copy /y \"{0}\" \"{1}\"",
Path.GetFullPath(outputName),
Path.GetFullPath(baselineName)
));
}
}
// Even if we don't have a baseline, we can check that the event names are OK.
if (0 <= eventName.IndexOf('(')) // Unknown events have () in them
{
// Some expected events we don't handle today.
if (data.EventName != "EventID(65534)" && // Manifest events
data.ProviderName != "Microsoft-Windows-DNS-Client" &&
eventName != "KernelTraceControl/ImageID/Opcode(34)" &&
eventName != "Windows Kernel/DiskIO/Opcode(16)" &&
eventName != "Windows Kernel/SysConfig/Opcode(37)")
{
Trace.WriteLine(string.Format("ERROR: File {0}: has unknown event {1} at {2:n3} MSec",
etlFilePath, eventName, data.TimeStampRelativeMSec));
// Assert throws an exception which gets swallowed in Process() so instead
// we remember that we failed and assert outside th callback.
unexpectedUnknownEvent = true;
}
}
};
/********************* PROCESSING ***************************/
traceSource.Process();
// Validation after processing, first we check that the histograms are the same as the baseline
if (mismatchCount == 0)
{
// We also want to check that the count of events is the same as the baseline.
bool histogramMismatch = false;
foreach (var keyValue in histogram)
{
var histogramLine = "COUNT " + keyValue.Key + ":" + keyValue.Value;
outputFile.WriteLine(histogramLine);
var expectedistogramLine = baselineFile.ReadLine();
lineNum++;
if (!histogramMismatch && expectedistogramLine != histogramLine)
{
histogramMismatch = true;
Trace.WriteLine(string.Format("ERROR: File {0}: histogram not equal on {1}", etlFilePath, lineNum));
Trace.WriteLine(string.Format(" Expected: {0}", histogramLine));
Trace.WriteLine(string.Format(" Actual : {0}", expectedistogramLine));
Trace.WriteLine("To Compare output and baseline (baseline is SECOND)");
Trace.WriteLine(string.Format(" windiff \"{0}\" \"{1}\"",
Path.GetFullPath(outputName),
Path.GetFullPath(baselineName)
));
Trace.WriteLine("To Update baseline file");
Trace.WriteLine(string.Format(" copy /y \"{0}\" \"{1}\"",
Path.GetFullPath(outputName),
Path.GetFullPath(baselineName)
));
anyFailure = true;
}
}
}
outputFile.Close();
if (mismatchCount > 0)
{
Trace.WriteLine(string.Format("ERROR: File {0}: had {1} mismatches", etlFilePath, mismatchCount));
}
// If this fires, check the output for the TraceLine just before it for more details.
Assert.IsFalse(unexpectedUnknownEvent, "Check trace output for details.");
Assert.IsTrue(lineNum > 0); // We had some events.
}
Assert.IsFalse(anyFailure, "Check trace output for details.");
#if !DEBUG
Assert.Inconclusive("Run with Debug build to get Thorough testing.");
#endif
}
public ICallTreeDataProvider Get()
{
var queryString = this.httpRequest.Query;
string filename = queryString["filename"];
string stacktype = queryString["stacktype"];
if (string.IsNullOrEmpty(filename))
{
throw new ArgumentNullException("filename");
}
if (string.IsNullOrEmpty(stacktype))
{
throw new ArgumentNullException("stacktype");
}
/* symbols and sources related parameters */
string sympathStr = (string)queryString["sympath"] ?? SymbolPath.MicrosoftSymbolServerPath;
SymbolPath symPath = new SymbolPath(sympathStr);
string defaultSymbolCache = symPath.DefaultSymbolCache();
// Normalize the symbol path.
symPath = symPath.InsureHasCache(defaultSymbolCache);
sympathStr = symPath.ToString();
string srcpath = (string)queryString["srcpath"];
//TODO FIX NOW: Dont spew to the Console, send it back to the client.
SymbolReader symbolReader = new SymbolReader(Console.Out, sympathStr);
if (srcpath != null)
{
symbolReader.SourcePath = srcpath;
}
string modulePatStr = (string)queryString["symLookupPats"] ?? @"^(clr|ntoskrnl|ntdll|.*\.ni)";
/* filtering parameters */
string start = (string)queryString["start"] ?? string.Empty;
string end = (string)queryString["end"] ?? string.Empty;
string incpats = (string)queryString["incpats"] ?? string.Empty;
string excpats = (string)queryString["excpats"] ?? string.Empty;
string foldpats = (string)queryString["foldpats"] ?? string.Empty;
string grouppats = (string)queryString["grouppats"] ?? string.Empty;
string foldpct = (string)queryString["foldpct"] ?? string.Empty;
string find = (string)queryString["find"] ?? string.Empty;
EtlxFile etlxFile;
// Do it twice so that XXX.etl.zip becomes XXX.
string etlxFilePath = Path.ChangeExtension(Path.ChangeExtension(filename, null), ".etlx");
lock (this.etlxCache)
{
if (this.etlxCache.TryGetValue(filename, out etlxFile))
{
if (etlxFile == null)
{
throw new ArgumentNullException("etlxFile");
}
}
else
{
etlxFile = new EtlxFile(filename)
{
Pending = true
};
this.etlxCache.Set(filename, etlxFile, this.cacheExpirationTime);
}
}
lock (etlxFile)
{
if (etlxFile.Pending)
{
if (!File.Exists(etlxFilePath))
{
// if it's a zip file
if (string.Equals(Path.GetExtension(filename), ".zip", StringComparison.OrdinalIgnoreCase))
{
//TODO FIX NOW: Dont spew to the Console, send it back to the client.
ZippedETLReader reader = new ZippedETLReader(filename, Console.Out);
reader.SymbolDirectory = defaultSymbolCache;
reader.EtlFileName = Path.ChangeExtension(etlxFilePath, etlExtension);
reader.UnpackAchive();
TraceLog.CreateFromEventTraceLogFile(reader.EtlFileName, etlxFilePath);
}
else
{
TraceLog.CreateFromEventTraceLogFile(filename, etlxFilePath);
}
}
etlxFile.TraceLog = TraceLog.OpenOrConvert(etlxFilePath);
etlxFile.Pending = false;
}
Regex modulePat = new Regex(modulePatStr, RegexOptions.IgnoreCase);
foreach (var moduleFile in etlxFile.TraceLog.ModuleFiles)
{
if (modulePat.IsMatch(moduleFile.Name))
{
etlxFile.TraceLog.CodeAddresses.LookupSymbolsForModule(symbolReader, moduleFile);
}
}
}
StackViewerSession stackViewerSession;
lock (this.stackViewerSessionCache)
{
var filterParams = new FilterParams {
Name = filename + stacktype, StartTimeRelativeMSec = start, EndTimeRelativeMSec = end, MinInclusiveTimePercent = foldpct, FoldRegExs = foldpats, IncludeRegExs = incpats, ExcludeRegExs = excpats, GroupRegExs = grouppats
};
var keyBuilder = new StringBuilder();
keyBuilder.Append(filterParams.Name).Append("?" + filterParams.StartTimeRelativeMSec).Append("?" + filterParams.EndTimeRelativeMSec).Append("?" + filterParams.MinInclusiveTimePercent).Append("?" + filterParams.FoldRegExs).Append("?" + filterParams.IncludeRegExs).Append("?" + filterParams.ExcludeRegExs).Append("?" + filterParams.GroupRegExs).Append("?" + find);
var stackViewerKey = keyBuilder.ToString();
if (this.stackViewerSessionCache.TryGetValue(stackViewerKey, out stackViewerSession))
{
if (stackViewerSession == null)
{
throw new ArgumentNullException("stackViewerSession");
}
}
else
{
stackViewerSession = new StackViewerSession(filename, stacktype, etlxFile.TraceLog, filterParams, symbolReader);
this.stackViewerSessionCache.Set(stackViewerKey, stackViewerSession, cacheExpirationTime);
}
}
lock (stackViewerSession)
{
if (stackViewerSession.Pending)
{
stackViewerSession.InitializeDataProvider();
stackViewerSession.Pending = false;
}
}
return(stackViewerSession.GetDataProvider());
}
public void ETW_MultiFileMergeAll_Basic()
{
PrepareTestData();
IEnumerable <string> fileNames = Directory.EnumerateFiles(UnZippedDataDir + "\\diaghub-dotnetcore3.1-win-x64-diagsession", "*.etl");
Output.WriteLine($"In {nameof(ETW_MultiFileMergeAll_Basic)}(\"{string.Join(", ", fileNames)}\")");
string etlFilePath = "diaghub-dotnetcore3.1-win-x64-diagsession";
Output.WriteLine(string.Format("Processing the file {0}, Making ETLX and scanning.", etlFilePath));
string eltxFilePath = Path.ChangeExtension(etlFilePath, ".etlx");
TraceEventDispatcher source = new ETWTraceEventSource(fileNames, TraceEventSourceType.MergeAll);
TraceLog traceLog = new TraceLog(TraceLog.CreateFromEventTraceLogFile(source, eltxFilePath));
Assert.Equal(95506, traceLog.EventCount);
var stopEvents = traceLog.Events.Filter(e => e.EventName == "Activity2Stop/Stop");
Assert.Equal(55, stopEvents.Count());
Assert.Equal((uint)13205, (uint)stopEvents.Last().EventIndex);
using (var file = new StreamReader($"{TestDataDir}\\diaghub-dotnetcore3.1-win-x64-diagsession.baseline.txt"))
{
var traceSource = traceLog.Events.GetSource();
traceSource.AllEvents += delegate(TraceEvent data)
{
string eventName = data.ProviderName + "/" + data.EventName;
// We are going to skip dynamic events from the CLR provider.
// The issue is that this depends on exactly which manifest is present
// on the machine, and I just don't want to deal with the noise of
// failures because you have a slightly different one.
if (data.ProviderName == "DotNet")
{
return;
}
// We don't want to use the manifest for CLR Private events since
// different machines might have different manifests.
if (data.ProviderName == "Microsoft-Windows-DotNETRuntimePrivate")
{
if (data.GetType().Name == "DynamicTraceEventData" || data.EventName.StartsWith("EventID"))
{
return;
}
}
// Same problem with classic OS events. We don't want to rely on the OS to parse since this could vary between baseline and test.
else if (data.ProviderName == "MSNT_SystemTrace")
{
// However we to allow a couple of 'known good' ones through so we test some aspects of the OS parsing logic in TraceEvent.
if (data.EventName != "SystemConfig/Platform" && data.EventName != "Image/KernelBase")
{
return;
}
}
// In theory we have the same problem with any event that the OS supplies the parsing. I dont want to be too aggressive about
// turning them off, however becasuse I want those code paths tested
// TODO FIX NOW, this is broken and should be fixed.
// We are hacking it here so we don't turn off the test completely.
if (eventName == "DotNet/CLR.SKUOrVersion")
{
return;
}
var evt = GeneralParsing.Parse(data);
var line = file.ReadLine();
Assert.Equal(evt, line);
};
traceSource.Process();
}
}
