// Scan through a trace and print a summary of the Chrome processes, optionally with
// CPU Usage details for Chrome and other key processes.
static void ProcessTrace(ITraceProcessor trace, bool showCPUUsage)
{
var pendingProcessData = trace.UseProcesses();
// Only request CPU scheduling data when it is actually needed, to avoid
// unecessary trace processing costs. Unfortunately this means that the
// scheduling data sources can't be declared with 'var'.
IPendingResult <ICpuSchedulingDataSource> pendingSchedulingData = null;
if (showCPUUsage)
{
pendingSchedulingData = trace.UseCpuSchedulingData();
}
trace.Process();
ICpuSchedulingDataSource schedulingData = null;
if (showCPUUsage)
{
schedulingData = pendingSchedulingData.Result;
}
// Get a List<ProcessSummary> of all Chrome processes.
var processSummaries = GetChromePaths(pendingProcessData.Result);
// Group all of the chrome.exe processes by browser Pid, then by type.
// pathByBrowserPid just maps from the browser Pid to the disk path to
// chrome.exe
var pathByBrowserPid = new Dictionary <int, string>();
// processesByBrowserPid is a dictionary that is indexed by the browser Pid.
// It contains a dictionary that is indexed by process type with each
// entry's payload being a list of Pids (for example, a list of renderer
// processes).
var processesByBrowserPid = new Dictionary <int, Dictionary <string, List <int> > >();
// parentPids is a dictionary that maps from Pids to parent Pids.
var parentPids = new Dictionary <int, int>();
// Dictionary of Pids and their types.
var typesByPid = new Dictionary <int, string>();
// Find the space-terminated word after 'type='.
// Mark the first .* as lazy/ungreedy/reluctant so that if there are multiple
// --type options (such as with the V8 Proxy Resolver utility process) the
// first one will win. Or, at least, that's what the comments in the Python
// version of this said.
var r = new Regex(@".*? --type=(?<type>[^ ]*) .*");
foreach (var entry in processSummaries)
{
var process = entry.Key;
var exePath = entry.Value;
if (process.ImageName == "chrome.exe")
{
int pid = process.Id;
parentPids[pid] = process.ParentId;
// Look for the process type on the command-line in the
// --type= option. If no type is found then assume it is the
// browser process. I could have looked for chrome.dll, but
// that may fail in the future. I could have looked for a chrome
// process whose parent is not chrome, but I didn't. There are
// many ways to do this.
string type;
int browserPid;
var match = r.Match(process.CommandLine);
if (match.Success)
{
type = match.Groups["type"].ToString();
if (type == "crashpad-handler")
{
type = "crashpad"; // Shorten the tag for better formatting
}
if (type == "renderer" && process.CommandLine.Contains(" --extension-process "))
{
// Extension processes are renderers with --extension-process on the command line.
type = "extension";
}
browserPid = process.ParentId;
}
else
{
type = "browser";
browserPid = pid;
pathByBrowserPid[browserPid] = exePath;
}
typesByPid[pid] = type;
// Retrieve or create the list of processes associated with this
// browser (parent) pid.
// This involves a lot of redundant dictionary lookups, but it is
// the cleanest way to do it.
if (!processesByBrowserPid.ContainsKey(browserPid))
{
processesByBrowserPid[browserPid] = new Dictionary <string, List <int> >();
}
if (!processesByBrowserPid[browserPid].ContainsKey(type))
{
processesByBrowserPid[browserPid][type] = new List <int>();
}
var pidList = processesByBrowserPid[browserPid][type];
pidList.Add(pid);
}
}
// Clean up the data, because process trees are never simple.
// Iterate through a copy of the keys so that we can modify the dictionary.
foreach (var browserPid in new List <int>(processesByBrowserPid.Keys))
{
var childPids = processesByBrowserPid[browserPid];
if (childPids.Count == 1)
{
// Linq magic to get the one-and-only key.
string childType = childPids.Keys.First();
string destType = null;
// In many cases there are two crash-handler processes and one is the
// parent of the other. This seems to be related to --monitor-self.
// This script will initially report the parent crashpad process as being a
// browser process, leaving the child orphaned. This fixes that up by
// looking for singleton crashpad browsers and then finding their real
// crashpad parent. This will then cause two crashpad processes to be
// listed, which is correct.
if (childType == "crashpad")
{
destType = childType;
}
// Also look for entries with parents in the list and no children. These
// represent child processes whose --type= option was too far along in the
// command line for ETW's 512-character capture to get. See crbug.com/614502
// for how this happened.
// Checking that there is only one entry (itself) in the list is important
// to avoid problems caused by Pid reuse that could cause one browser process
// to appear to be another browser process' parent.
else if (childType == "browser")
{
destType = "gpu???";
}
// The browserPid *should* always be present, but in a large enough corpus
// of traces, all bets are off. This assumption failed in a 20-hour heap
// snapshot trace.
if (parentPids.ContainsKey(browserPid))
{
// The childPids["browser"] entry needs to be appended to its
// parent/grandparent process since that is its browser process.
int parentPid = parentPids[browserPid];
// Create the destination type if necessary (needed for gpu???,
// not needed for crashpad). Handle missing data.
if (processesByBrowserPid.ContainsKey(parentPid))
{
if (!processesByBrowserPid[parentPid].ContainsKey(destType))
{
processesByBrowserPid[parentPid][destType] = new List <int>();
}
processesByBrowserPid[parentPid][destType].Add(childPids[childType][0]);
// Remove the fake 'browser' entry so that we don't try to print it.
processesByBrowserPid.Remove(browserPid);
}
}
}
}
// Map from PID to CPUUsageDetails.
var execTimes = new Dictionary <int, CPUUsageDetails>();
if (showCPUUsage)
{
var names = new string[] { "chrome.exe", "dwm.exe", "audiodg.exe", "System", "MsMpEng.exe", "software_reporter_tool.exe" };
// Scan through the context-switch data to build up how much time
// was spent by interesting process.
foreach (var slice in schedulingData.CpuTimeSlices)
{
// Yep, this happens.
if (slice.Process == null)
{
continue;
}
// Ignore non-interesting names. Only accumulate for chrome.exe and
// processes that are known to be related or interesting.
// An existence check in an array is O(n) but because the array is
// short this is probably faster than using a dictionary.
if (!names.Contains(slice.Process.ImageName))
{
continue;
}
execTimes.TryGetValue(slice.Process.Id, out CPUUsageDetails last);
last.imageName = slice.Process.ImageName;
last.ns += slice.Duration.Nanoseconds;
last.contextSwitches += 1;
execTimes[slice.Process.Id] = last;
}
foreach (var times in execTimes)
{
CPUUsageDetails details = times.Value;
// Print details about other interesting processes:
if (details.imageName != "chrome.exe")
{
Console.WriteLine("{0,11} - {1,6} context switches, {2,8:0.00} ms CPU", details.imageName, details.contextSwitches, details.ns / 1e6);
}
}
Console.WriteLine();
}
if (processesByBrowserPid.Count > 0)
{
Console.WriteLine("Chrome PIDs by process type:");
}
else
{
Console.WriteLine("No Chrome processes found.");
}
var browserPids = new List <int>(processesByBrowserPid.Keys);
browserPids.Sort();
foreach (var browserPid in browserPids)
{
// |processes| is a Dictionary<type, List<pid>>
var processes = processesByBrowserPid[browserPid];
// Total up how many processes there are in this instance.
var detailsByType = new Dictionary <string, CPUUsageDetails>();
int totalProcesses = 0;
var detailsTotal = new CPUUsageDetails();
foreach (var type in processes)
{
totalProcesses += type.Value.Count;
if (showCPUUsage)
{
var detailsSubTotal = new CPUUsageDetails();
foreach (int pid in type.Value)
{
execTimes.TryGetValue(pid, out CPUUsageDetails details);
detailsTotal.ns += details.ns;
detailsTotal.contextSwitches += details.contextSwitches;
detailsSubTotal.ns += details.ns;
detailsSubTotal.contextSwitches += details.contextSwitches;
}
detailsByType[type.Key] = detailsSubTotal;
}
}
// Print the browser path.
if (showCPUUsage)
{
Console.WriteLine("{0} ({1}) - {2} context switches, {3,8:0.00} ms CPU, {4} processes",
pathByBrowserPid[browserPid], browserPid, detailsTotal.contextSwitches,
detailsTotal.ns / 1e6, totalProcesses);
}
else
{
// See earlier note about how the browserPid may be missing.
string browserPath = "Unknown parent";
if (pathByBrowserPid.ContainsKey(browserPid))
{
browserPath = pathByBrowserPid[browserPid];
}
Console.WriteLine("{0} ({1}) - {2} processes", browserPath, browserPid, totalProcesses);
}
// Sort the types alphabetically for consistent printing.
var types = new List <KeyValuePair <string, List <int> > >(processes);
types.Sort((x, y) => x.Key.CompareTo(y.Key));
// Print all of the child processes, grouped by type.
foreach (var type in types)
{
// |type| contains type and List<pid>
// TODO: change this to ,12 for ppapi-broker
if (showCPUUsage)
{
CPUUsageDetails detailsSum = detailsByType[type.Key];
Console.Write(" {0,-11} : total - {1,6} context switches, {2,8:0.00} ms CPU", type.Key, detailsSum.contextSwitches, detailsSum.ns / 1e6);
}
else
{
Console.Write(" {0,-11} : ", type.Key);
}
type.Value.Sort();
foreach (var pid in type.Value)
{
if (showCPUUsage)
{
Console.Write("\n ");
execTimes.TryGetValue(pid, out CPUUsageDetails details);
if (details.contextSwitches > 0)
{
Console.Write("{0,5} - {1,6} context switches, {2,8:0.00} ms CPU", pid, details.contextSwitches, details.ns / 1e6);
}
else
{
Console.Write("{0,5}", pid);
}
}
else
{
Console.Write("{0} ", pid);
}
}
Console.WriteLine();
}
Console.WriteLine();
}
}
// 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");
}
}
