// Scan through a trace and print a summary of the system activity, with
// svchost.exe and powershell process purposes annotated, chrome and
// some other processes grouped, and with sampled data summarized by the
// module it hits in and which modules are on the stacks.
static void ProcessTrace(ITraceProcessor trace, string[] moduleList)
{
// metadata is retrieved directly instead of being retrieved after
// trace.Process().
var metadata = trace.UseMetadata();
// Needed for precise CPU usage calculations.
var pendingSchedulingData = trace.UseCpuSchedulingData();
// Needed for processor count and memory size.
var pendingSystemMetadata = trace.UseSystemMetadata();
// Needed for PID to service mapping.
var pendingServices = trace.UseServices();
// Needed for seeing what modules samples hit in.
var pendingSamplingData = trace.UseCpuSamplingData();
trace.Process();
// Convert from pending to actual data.
var schedulingData = pendingSchedulingData.Result;
var systemMetadata = pendingSystemMetadata.Result;
var services = pendingServices.Result;
var samplingData = pendingSamplingData.Result;
// Print some high-level data about the trace and system.
var traceDuration = metadata.AnalyzerDisplayedDuration;
Console.WriteLine("Trace length is {0:0.00} seconds, system has {1} logical processors, {2}.",
traceDuration.TotalSeconds, systemMetadata.ProcessorCount, systemMetadata.UsableMemorySize);
Console.WriteLine();
// Map from an IProcess to CPUUsageDetails.
var execTimes = new Dictionary <IProcess, CPUUsageDetails>();
// Scan through the context-switch data to build up how much time
// was spent by each process.
foreach (var slice in schedulingData.CpuTimeSlices)
{
// Yep, this happens.
if (slice.Process == null)
{
continue;
}
execTimes.TryGetValue(slice.Process, out CPUUsageDetails last);
last.ns += slice.Duration.Nanoseconds;
last.contextSwitches += 1;
execTimes[slice.Process] = last;
}
// Report on CPU usage for theses processes by name instead of by
// process. That is, add same-named processes together.
string[] sumNames = { "chrome.exe", "WmiPrvSE.exe", };
var sumsNs = new long[sumNames.Length];
// Scan through the per-process CPU consumption data
var report = new List <Tuple <double, string> >();
foreach (var times in execTimes)
{
var process = times.Key;
CPUUsageDetails details = times.Value;
// See if we want to sum this process name.
int i = Array.IndexOf(sumNames, process.ImageName);
if (i >= 0)
{
sumsNs[i] += times.Value.ns;
continue;
}
// Find the script name or service name that is associated with this
// process so that our report associates the CPU time with a script
// or service.
string context = "";
var commandLine = process.CommandLine;
if (process.ImageName == "svchost.exe")
{
// Look for this pid in the snapshots. This should handle it if
// multiple services exist in one process but this has not been
// tested.
foreach (var service in services.Snapshots)
{
if (service.ProcessId == process.Id)
{
if (context.Length > 0)
{
context += ' ';
}
context += service.Name;
}
}
}
else if (process.ImageName == "powershell.exe")
{
// Look for .ps1 and then search backwards for a space or slash character.
var scriptEnd = commandLine.IndexOf(".ps1");
if (scriptEnd > 0)
{
// Look for a slash or space character to mark the beginning of
// the file name of the script.
var slash = commandLine.LastIndexOf('\\', scriptEnd);
var space = commandLine.LastIndexOf(' ', scriptEnd);
var start = Math.Max(slash, space) + 1;
context = commandLine.Substring(start, scriptEnd + 4 - start);
}
// If no .ps1 filename was found then try something else.
if (context.Length == 0)
{
// Grab the last parameter. This really needs to handle quotes to
// be useful.
var parts = commandLine.Split(' ');
context = parts[parts.Length - 1];
}
}
else if (process.ImageName == "ruby.exe")
{
// Grab the start of the command-line and hope that helps.
context = commandLine.Substring(0, Math.Min(20, commandLine.Length));
}
double timeSeconds = details.ns / 1e9;
report.Add(new Tuple <double, string>(timeSeconds, string.Format("{0,20} ({1,5}) - {2}", process.ImageName, process.Id, context)));
}
// Add in the processes that we sum by name instead of by processes.
for (int i = 0; i < sumNames.Length; ++i)
{
double timeSeconds = sumsNs[i] / 1e9;
report.Add(new Tuple <double, string>(timeSeconds, string.Format("{0,20}", sumNames[i])));
}
// Sort the data by CPU time consumed and print the busiest processes:
report.Sort();
report.Reverse();
foreach (var r in report)
{
// Arbitrary threshold so that we ignore boring data.
if (r.Item1 > 2.0)
{
double percentage = r.Item1 / (double)traceDuration.TotalSeconds;
Console.WriteLine("{0,9:P} of a core, {1,8:0.00} s CPU, {2}", percentage, r.Item1, r.Item2);
}
}
// Record two dictionaries that map from modules to sample counts.
// One is for samples that hit in that module, the other is for samples
// that hit when an "interesting" module is on the stack.
// Track by module name rather than IImage because some DLLs (ntdll.dll)
// show up as many different IImage objects, which makes for a confusing
// report.
var samplesByImage = new Dictionary <string, ulong>();
var stackSamplesByImage = new Dictionary <string, ulong>();
foreach (var sample in samplingData.Samples)
{
{
// Attribute samples to the module they hit in. This gives a
// sense of where CPU time is being spent across all processes
// on the system. In some cases this can give hints - perhaps a
// lower bound - on the cost of modules which inject themselves
// into all processes.
if (sample.Image != null)
{
samplesByImage.TryGetValue(sample.Image.FileName, out ulong count);
++count;
samplesByImage[sample.Image.FileName] = count;
}
}
if (moduleList != null && sample.Stack != null)
{
// Attributes samples to interesting modules that are on the stack.
// In some cases an injected module may ask the OS or other modules
// to do work on its behalf. If antivirus DLLs are on the
// stack but not currently executing then the executing code *may*
// be doing work on their behalf, or not. Thus, gives gives a
// rough upper bound on the cost of these systems. Note that only the
// first module hit is counted.
foreach (var frame in sample.Stack.Frames)
{
if (frame.Image != null && frame.Image.FileName != null)
{
string imageName = frame.Image.FileName;
if (moduleList.Contains(imageName))
{
stackSamplesByImage.TryGetValue(imageName, out ulong count);
++count;
stackSamplesByImage[imageName] = count;
break;
}
}
}
}
}
Console.WriteLine();
int totalSamples = samplingData.Samples.Count;
Console.WriteLine("Exclusive samples by module (out of {0:#,#} samples total):", totalSamples);
PrintSampleData(new List <KeyValuePair <string, ulong> >(samplesByImage),
totalSamples, "{0,9:#,#} samples {1,6:P} in {2}");
if (moduleList != null)
{
Console.WriteLine("");
Console.WriteLine("Inclusive (stacks containing them) samples (out of {0:#,#} samples total):", totalSamples);
PrintSampleData(new List <KeyValuePair <string, ulong> >(stackSamplesByImage),
totalSamples, "{0,9:#,#} samples {1,6:P} with {2} on the call stack");
}
}
