private void StopMonitor()
{
try
{
_session.Stop();
}
catch (EndOfStreamException ex)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
Debug.WriteLine($"[ERROR] {ex.ToString()}");
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
// On non-abrupt exits, the socket may be already closed by the runtime and we won't be able to send a stop request through it.
catch (ServerNotAvailableException)
{
}
_renderer.Stop();
}
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, string counters, IConsole console, int processId, int refreshInterval, string name)
{
if (!ValidateAndSetProcessId(processId, name))
{
return(0);
}
try
{
InitializeCounterList(counters, counter_list);
_ct = ct;
_console = console;
_interval = refreshInterval;
_renderer = new ConsoleWriter();
if (!BuildDiagnosticsClient())
{
return(0);
}
int ret = await Start();
ProcessLauncher.Launcher.Cleanup();
return(ret);
}
catch (OperationCanceledException)
{
try
{
_session.Stop();
}
catch (Exception) {} // Swallow all exceptions for now.
console.Out.WriteLine($"Complete");
return(1);
}
}
public Task <Stream> StartCpuTrace(int pid, int durationSeconds, CancellationToken cancellationToken)
{
if ((durationSeconds < 1) || (durationSeconds > MaxTraceSeconds))
{
throw new InvalidOperationException("Invalid duration");
}
//TODO Should we limit only 1 trace per file?
var client = new DiagnosticsClient(pid);
//TODO Pull event providers from the configuration.
var cpuProviders = new EventPipeProvider[] {
new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", System.Diagnostics.Tracing.EventLevel.Informational),
new EventPipeProvider("Microsoft-Windows-DotNETRuntime", System.Diagnostics.Tracing.EventLevel.Informational, (long)Tracing.Parsers.ClrTraceEventParser.Keywords.Default)
};
EventPipeSession session = client.StartEventPipeSession(cpuProviders, requestRundown: true);
CancellationTokenSource linkedTokenSource = CancellationTokenSource.CreateLinkedTokenSource(_tokenSource.Token, cancellationToken);
Task traceTask = Task.Run(async() =>
{
try
{
await Task.Delay(TimeSpan.FromSeconds(durationSeconds), linkedTokenSource.Token);
}
finally
{
session.Stop();
linkedTokenSource.Dispose();
//We rely on the caller to Dispose the EventStream file.
}
}, CancellationToken.None);
return(Task.FromResult(session.EventStream));
}
private static void StopSession(EventPipeSession session)
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before collection started and got rid of a pipe that once existed.
// Since we are catching this at the end of a session we know that the pipe once existed (otherwise the exception would've
// been thrown at the beginning directly)
catch (PlatformNotSupportedException)
{
}
// On non-abrupt exits, the socket may be already closed by the runtime and we won't be able to send a stop request through it.
catch (ServerNotAvailableException)
{
}
}
public void Dispose()
{
try {
_session?.Stop();
} catch (ServerNotAvailableException) {
}
_session?.Dispose();
}
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, string counters, IConsole console, int processId, int refreshInterval, string name, string diagnosticPort, bool resumeRuntime)
{
if (!ProcessLauncher.Launcher.HasChildProc && !CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out _processId))
{
return(0);
}
shouldExit = new ManualResetEvent(false);
_ct.Register(() => shouldExit.Set());
DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-counters", 10);
using (DiagnosticsClientHolder holder = await builder.Build(ct, _processId, diagnosticPort, showChildIO: false, printLaunchCommand: false))
{
if (holder == null)
{
return(1);
}
try
{
InitializeCounterList(counters, counter_list);
_ct = ct;
_console = console;
_interval = refreshInterval;
_renderer = new ConsoleWriter();
_diagnosticsClient = holder.Client;
shouldResumeRuntime = ProcessLauncher.Launcher.HasChildProc || !string.IsNullOrEmpty(diagnosticPort) || resumeRuntime;
int ret = await Start();
ProcessLauncher.Launcher.Cleanup();
return(ret);
}
catch (OperationCanceledException)
{
try
{
_session.Stop();
}
catch (Exception) { } // Swallow all exceptions for now.
console.Out.WriteLine($"Complete");
return(1);
}
}
}
public void Stop()
{
if (_process != null)
{
_session.Stop();
_counters = null;
_task = null;
_process = null;
}
}
public async Task <int> Monitor(CancellationToken ct, List <string> counter_list, IConsole console, int processId, int refreshInterval, string name)
{
if (name != null)
{
if (processId != 0)
{
Console.WriteLine("Can only specify either --name or --process-id option.");
return(0);
}
processId = CommandUtils.FindProcessIdWithName(name);
if (processId < 0)
{
return(0);
}
}
try
{
_ct = ct;
_counterList = counter_list; // NOTE: This variable name has an underscore because that's the "name" that the CLI displays. System.CommandLine doesn't like it if we change the variable to camelcase.
_console = console;
_processId = processId;
_interval = refreshInterval;
_renderer = new ConsoleWriter();
_diagnosticsClient = new DiagnosticsClient(processId);
return(await Start());
}
catch (OperationCanceledException)
{
try
{
_session.Stop();
}
catch (Exception) {} // Swallow all exceptions for now.
console.Out.WriteLine($"Complete");
return(1);
}
}
private static void StopSession(EventPipeSession session)
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
}
/// <summary>
/// Collects a diagnostic trace from a currently running process.
/// </summary>
/// <param name="ct">The cancellation token</param>
/// <param name="console"></param>
/// <param name="processId">The process to collect the trace from.</param>
/// <param name="output">The output path for the collected trace data.</param>
/// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param>
/// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param>
/// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param>
/// <param name="format">The desired format of the created trace file.</param>
/// <param name="duration">The duration of trace to be taken. </param>
/// <param name="clrevents">A list of CLR events to be emitted.</param>
/// <param name="clreventlevel">The verbosity level of CLR events</param>
/// <returns></returns>
private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel)
{
try
{
Debug.Assert(output != null);
Debug.Assert(profile != null);
bool hasConsole = console.GetTerminal() != null;
if (hasConsole)
{
Console.Clear();
}
if (processId < 0)
{
Console.Error.WriteLine("Process ID should not be negative.");
return(ErrorCodes.ArgumentError);
}
else if (processId == 0)
{
Console.Error.WriteLine("--process-id is required");
return(ErrorCodes.ArgumentError);
}
if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0)
{
Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'");
profile = "cpu-sampling";
}
Dictionary <string, string> enabledBy = new Dictionary <string, string>();
var providerCollection = Extensions.ToProviders(providers);
foreach (EventPipeProvider providerCollectionProvider in providerCollection)
{
enabledBy[providerCollectionProvider.Name] = "--providers ";
}
if (profile.Length != 0)
{
var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles
.FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase));
if (selectedProfile == null)
{
Console.Error.WriteLine($"Invalid profile name: {profile}");
return(ErrorCodes.ArgumentError);
}
Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy);
}
// Parse --clrevents parameter
if (clrevents.Length != 0)
{
// Ignore --clrevents if CLR event provider was already specified via --profile or --providers command.
if (enabledBy.ContainsKey(Extensions.CLREventProviderName))
{
Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command.");
}
else
{
var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel);
providerCollection.Add(clrProvider);
enabledBy[Extensions.CLREventProviderName] = "--clrevents";
}
}
if (providerCollection.Count <= 0)
{
Console.Error.WriteLine("No providers were specified to start a trace.");
return(ErrorCodes.ArgumentError);
}
PrintProviders(providerCollection, enabledBy);
var process = Process.GetProcessById(processId);
var shouldExit = new ManualResetEvent(false);
var shouldStopAfterDuration = duration != default(TimeSpan);
var failed = false;
var terminated = false;
var rundownRequested = false;
System.Timers.Timer durationTimer = null;
ct.Register(() => shouldExit.Set());
var diagnosticsClient = new DiagnosticsClient(processId);
using (VirtualTerminalMode vTermMode = VirtualTerminalMode.TryEnable())
{
EventPipeSession session = null;
try
{
session = diagnosticsClient.StartEventPipeSession(providerCollection, true);
}
catch (DiagnosticsClientException e)
{
Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}");
}
if (session == null)
{
Console.Error.WriteLine("Unable to create session.");
return(ErrorCodes.SessionCreationError);
}
if (shouldStopAfterDuration)
{
durationTimer = new System.Timers.Timer(duration.TotalMilliseconds);
durationTimer.Elapsed += (s, e) => shouldExit.Set();
durationTimer.AutoReset = false;
}
var collectingTask = new Task(() =>
{
try
{
var stopwatch = new Stopwatch();
durationTimer?.Start();
stopwatch.Start();
using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write))
{
Console.Out.WriteLine($"Process : {process.MainModule.FileName}");
Console.Out.WriteLine($"Output File : {fs.Name}");
if (shouldStopAfterDuration)
{
Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}");
}
Console.Out.WriteLine("\n\n");
var buffer = new byte[16 * 1024];
while (true)
{
int nBytesRead = session.EventStream.Read(buffer, 0, buffer.Length);
if (nBytesRead <= 0)
{
break;
}
fs.Write(buffer, 0, nBytesRead);
if (!rundownRequested)
{
if (hasConsole)
{
lineToClear = Console.CursorTop - 1;
ResetCurrentConsoleLine(vTermMode.IsEnabled);
}
Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fs.Length)}");
Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit...");
Debug.WriteLine($"PACKET: {Convert.ToBase64String(buffer, 0, nBytesRead)} (bytes {nBytesRead})");
}
}
}
}
catch (Exception ex)
{
failed = true;
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
}
finally
{
terminated = true;
shouldExit.Set();
}
});
collectingTask.Start();
do
{
while (!Console.KeyAvailable && !shouldExit.WaitOne(250))
{
}
} while (!shouldExit.WaitOne(0) && Console.ReadKey(true).Key != ConsoleKey.Enter);
if (!terminated)
{
durationTimer?.Stop();
if (hasConsole)
{
lineToClear = Console.CursorTop;
ResetCurrentConsoleLine(vTermMode.IsEnabled);
}
Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced.");
rundownRequested = true;
session.Stop();
}
await collectingTask;
}
Console.Out.WriteLine();
Console.Out.WriteLine("Trace completed.");
if (format != TraceFileFormat.NetTrace)
{
TraceFileFormatConverter.ConvertToFormat(format, output.FullName);
}
return(failed ? ErrorCodes.TracingError : 0);
}
catch (Exception ex)
{
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
return(ErrorCodes.UnknownError);
}
}
public async Task <int> Monitor(
CancellationToken ct,
List <string> counter_list,
string counters,
IConsole console,
int processId,
int refreshInterval,
string name,
string diagnosticPort,
bool resumeRuntime,
int maxHistograms,
int maxTimeSeries)
{
try
{
// System.CommandLine does have an option to specify arguments as uint and it would validate they are non-negative. However the error
// message is "Cannot parse argument '-1' for option '--maxTimeSeries' as expected type System.UInt32" which is not as user friendly.
// If there was another option to leverage System.CommandLine that provides a little more user friendly error message we could switch
// to it.
ValidateNonNegative(maxHistograms, nameof(maxHistograms));
ValidateNonNegative(maxTimeSeries, nameof(maxTimeSeries));
if (!ProcessLauncher.Launcher.HasChildProc && !CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out _processId))
{
return(ReturnCode.ArgumentError);
}
_ct.Register(() => _shouldExit.TrySetResult(ReturnCode.Ok));
DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-counters", 10);
using (DiagnosticsClientHolder holder = await builder.Build(ct, _processId, diagnosticPort, showChildIO: false, printLaunchCommand: false))
{
if (holder == null)
{
return(ReturnCode.Ok);
}
try
{
_console = console;
// the launch command may misinterpret app arguments as the old space separated
// provider list so we need to ignore it in that case
_counterList = ConfigureCounters(counters, _processId != 0 ? counter_list : null);
_ct = ct;
_interval = refreshInterval;
_maxHistograms = maxHistograms;
_maxTimeSeries = maxTimeSeries;
_renderer = new ConsoleWriter();
_diagnosticsClient = holder.Client;
_resumeRuntime = resumeRuntime;
int ret = await Start();
ProcessLauncher.Launcher.Cleanup();
return(ret);
}
catch (OperationCanceledException)
{
try
{
_session.Stop();
}
catch (Exception) { } // Swallow all exceptions for now.
console.Out.WriteLine($"Complete");
return(ReturnCode.Ok);
}
}
}
catch (CommandLineErrorException e)
{
console.Error.WriteLine(e.Message);
return(ReturnCode.ArgumentError);
}
}
public void Stop()
{
m_session.Stop();
}
/// <summary>
/// Collects a diagnostic trace from a currently running process or launch a child process and trace it.
/// Append -- to the collect command to instruct the tool to run a command and trace it immediately. By default the IO from this process is hidden, but the --show-child-io option may be used to show the child process IO.
/// </summary>
/// <param name="ct">The cancellation token</param>
/// <param name="console"></param>
/// <param name="processId">The process to collect the trace from.</param>
/// <param name="name">The name of process to collect the trace from.</param>
/// <param name="output">The output path for the collected trace data.</param>
/// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param>
/// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param>
/// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param>
/// <param name="format">The desired format of the created trace file.</param>
/// <param name="duration">The duration of trace to be taken. </param>
/// <param name="clrevents">A list of CLR events to be emitted.</param>
/// <param name="clreventlevel">The verbosity level of CLR events</param>
/// <param name="port">Path to the diagnostic port to be created.</param>
/// <param name="showchildio">Should IO from a child process be hidden.</param>
/// <returns></returns>
private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel, string name, string diagnosticPort, bool showchildio)
{
int ret = 0;
bool collectionStopped = false;
bool cancelOnEnter = true;
bool cancelOnCtrlC = true;
bool printStatusOverTime = true;
try
{
Debug.Assert(output != null);
Debug.Assert(profile != null);
if (ProcessLauncher.Launcher.HasChildProc && showchildio)
{
// If showing IO, then all IO (including CtrlC) behavior is delegated to the child process
cancelOnCtrlC = false;
cancelOnEnter = false;
printStatusOverTime = false;
}
else
{
cancelOnCtrlC = true;
cancelOnEnter = !Console.IsInputRedirected;
printStatusOverTime = !Console.IsInputRedirected;
}
if (!cancelOnCtrlC)
{
ct = CancellationToken.None;
}
if (!ProcessLauncher.Launcher.HasChildProc)
{
if (showchildio)
{
Console.WriteLine("--show-child-io must not be specified when attaching to a process");
return(ErrorCodes.ArgumentError);
}
if (CommandUtils.ValidateArgumentsForAttach(processId, name, diagnosticPort, out int resolvedProcessId))
{
processId = resolvedProcessId;
}
else
{
return(ErrorCodes.ArgumentError);
}
}
else if (!CommandUtils.ValidateArgumentsForChildProcess(processId, name, diagnosticPort))
{
return(ErrorCodes.ArgumentError);
}
if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0)
{
Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'");
profile = "cpu-sampling";
}
Dictionary <string, string> enabledBy = new Dictionary <string, string>();
var providerCollection = Extensions.ToProviders(providers);
foreach (EventPipeProvider providerCollectionProvider in providerCollection)
{
enabledBy[providerCollectionProvider.Name] = "--providers ";
}
if (profile.Length != 0)
{
var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles
.FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase));
if (selectedProfile == null)
{
Console.Error.WriteLine($"Invalid profile name: {profile}");
return(ErrorCodes.ArgumentError);
}
Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy);
}
// Parse --clrevents parameter
if (clrevents.Length != 0)
{
// Ignore --clrevents if CLR event provider was already specified via --profile or --providers command.
if (enabledBy.ContainsKey(Extensions.CLREventProviderName))
{
Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command.");
}
else
{
var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel);
providerCollection.Add(clrProvider);
enabledBy[Extensions.CLREventProviderName] = "--clrevents";
}
}
if (providerCollection.Count <= 0)
{
Console.Error.WriteLine("No providers were specified to start a trace.");
return(ErrorCodes.ArgumentError);
}
PrintProviders(providerCollection, enabledBy);
DiagnosticsClient diagnosticsClient;
Process process;
DiagnosticsClientBuilder builder = new DiagnosticsClientBuilder("dotnet-trace", 10);
bool shouldResumeRuntime = ProcessLauncher.Launcher.HasChildProc || !string.IsNullOrEmpty(diagnosticPort);
var shouldExit = new ManualResetEvent(false);
ct.Register(() => shouldExit.Set());
using (DiagnosticsClientHolder holder = await builder.Build(ct, processId, diagnosticPort, showChildIO: showchildio, printLaunchCommand: true))
{
// if builder returned null, it means we received ctrl+C while waiting for clients to connect. Exit gracefully.
if (holder == null)
{
return(await Task.FromResult(ret));
}
diagnosticsClient = holder.Client;
if (shouldResumeRuntime)
{
process = Process.GetProcessById(holder.EndpointInfo.ProcessId);
}
else
{
process = Process.GetProcessById(processId);
}
string processMainModuleFileName = "";
// Reading the process MainModule filename can fail if the target process closes
// or isn't fully setup. Retry a few times to attempt to address the issue
for (int attempts = 0; true; attempts++)
{
try
{
processMainModuleFileName = process.MainModule.FileName;
break;
}
catch
{
if (attempts > 10)
{
Console.Error.WriteLine("Unable to examine process.");
return(ErrorCodes.SessionCreationError);
}
Thread.Sleep(200);
}
}
if (String.Equals(output.Name, DefaultTraceName, StringComparison.OrdinalIgnoreCase))
{
DateTime now = DateTime.Now;
var processMainModuleFileInfo = new FileInfo(processMainModuleFileName);
output = new FileInfo($"{processMainModuleFileInfo.Name}_{now:yyyyMMdd}_{now:HHmmss}.nettrace");
}
var shouldStopAfterDuration = duration != default(TimeSpan);
var rundownRequested = false;
System.Timers.Timer durationTimer = null;
using (VirtualTerminalMode vTermMode = printStatusOverTime ? VirtualTerminalMode.TryEnable() : null)
{
EventPipeSession session = null;
try
{
session = diagnosticsClient.StartEventPipeSession(providerCollection, true, (int)buffersize);
if (shouldResumeRuntime)
{
diagnosticsClient.ResumeRuntime();
}
}
catch (DiagnosticsClientException e)
{
Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}");
}
if (session == null)
{
Console.Error.WriteLine("Unable to create session.");
return(ErrorCodes.SessionCreationError);
}
if (shouldStopAfterDuration)
{
durationTimer = new System.Timers.Timer(duration.TotalMilliseconds);
durationTimer.Elapsed += (s, e) => shouldExit.Set();
durationTimer.AutoReset = false;
}
var stopwatch = new Stopwatch();
durationTimer?.Start();
stopwatch.Start();
LineRewriter rewriter = null;
using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write))
{
Console.Out.WriteLine($"Process : {processMainModuleFileName}");
Console.Out.WriteLine($"Output File : {fs.Name}");
if (shouldStopAfterDuration)
{
Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}");
}
Console.Out.WriteLine("\n\n");
var fileInfo = new FileInfo(output.FullName);
Task copyTask = session.EventStream.CopyToAsync(fs);
Task shouldExitTask = copyTask.ContinueWith((task) => shouldExit.Set());
if (printStatusOverTime)
{
rewriter = new LineRewriter {
LineToClear = Console.CursorTop - 1
};
Console.CursorVisible = false;
}
Action printStatus = () =>
{
if (printStatusOverTime)
{
rewriter?.RewriteConsoleLine();
fileInfo.Refresh();
Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fileInfo.Length)}");
Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit...");
}
if (rundownRequested)
{
Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced.");
}
};
while (!shouldExit.WaitOne(100) && !(cancelOnEnter && Console.KeyAvailable && Console.ReadKey(true).Key == ConsoleKey.Enter))
{
printStatus();
}
// if the CopyToAsync ended early (target program exited, etc.), the we don't need to stop the session.
if (!copyTask.Wait(0))
{
// Behavior concerning Enter moving text in the terminal buffer when at the bottom of the buffer
// is different between Console/Terminals on Windows and Mac/Linux
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows) &&
printStatusOverTime &&
rewriter != null &&
Math.Abs(Console.CursorTop - Console.BufferHeight) == 1)
{
rewriter.LineToClear--;
}
collectionStopped = true;
durationTimer?.Stop();
rundownRequested = true;
session.Stop();
do
{
printStatus();
} while (!copyTask.Wait(100));
}
// At this point the copyTask will have finished, so wait on the shouldExitTask in case it threw
// an exception or had some other interesting behavior
shouldExitTask.Wait();
}
Console.Out.WriteLine($"\nTrace completed.");
if (format != TraceFileFormat.NetTrace)
{
TraceFileFormatConverter.ConvertToFormat(format, output.FullName);
}
}
if (!collectionStopped && !ct.IsCancellationRequested)
{
// If the process is shutting down by itself print the return code from the process.
// Capture this before leaving the using, as the Dispose of the DiagnosticsClientHolder
// may terminate the target process causing it to have the wrong error code
if (ProcessLauncher.Launcher.HasChildProc && ProcessLauncher.Launcher.ChildProc.WaitForExit(5000))
{
ret = ProcessLauncher.Launcher.ChildProc.ExitCode;
Console.WriteLine($"Process exited with code '{ret}'.");
collectionStopped = true;
}
}
}
}
catch (Exception ex)
{
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
ret = ErrorCodes.TracingError;
collectionStopped = true;
}
finally
{
if (printStatusOverTime)
{
if (console.GetTerminal() != null)
{
Console.CursorVisible = true;
}
}
if (ProcessLauncher.Launcher.HasChildProc)
{
if (!collectionStopped || ct.IsCancellationRequested)
{
ret = ErrorCodes.TracingError;
}
// If we launched a child proc that hasn't exited yet, terminate it before we exit.
if (!ProcessLauncher.Launcher.ChildProc.HasExited)
{
ProcessLauncher.Launcher.ChildProc.Kill();
}
}
}
return(await Task.FromResult(ret));
}
public void ProcessEvents(
string applicationName,
string serviceName,
int processId,
string replicaName,
IDictionary <string, string> metrics,
CancellationToken cancellationToken)
{
var hasEventPipe = false;
for (var i = 0; i < 10; ++i)
{
if (DiagnosticsClient.GetPublishedProcesses().Contains(processId))
{
hasEventPipe = true;
break;
}
if (cancellationToken.IsCancellationRequested)
{
return;
}
Thread.Sleep(500);
}
if (!hasEventPipe)
{
_logger.LogInformation("Process id {PID}, does not support event pipe", processId);
return;
}
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId);
// Create the logger factory for this replica
using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder));
var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName, replicaName));
var providers = new List <EventPipeProvider>()
{
// Runtime Metrics
new EventPipeProvider(
SystemRuntimeEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
MicrosoftAspNetCoreHostingEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
GrpcAspNetCoreServer,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Application Metrics
new EventPipeProvider(
applicationName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Logging
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
EventLevel.LogAlways,
(long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage)
),
// Distributed Tracing
// Activity correlation
new EventPipeProvider(TplEventSource,
keywords: 0x80,
eventLevel: EventLevel.LogAlways),
// Diagnostic source events
new EventPipeProvider(DiagnosticSourceEventSource,
keywords: 0x1 | 0x2,
eventLevel: EventLevel.Verbose,
arguments: new Dictionary <string, string>
{
{ "FilterAndPayloadSpecs", DiagnosticFilterString }
})
};
while (!cancellationToken.IsCancellationRequested)
{
EventPipeSession session = null;
var client = new DiagnosticsClient(processId);
try
{
session = client.StartEventPipeSession(providers);
}
catch (EndOfStreamException)
{
break;
}
// If the process has already exited, a ServerNotAvailableException will be thrown.
catch (ServerNotAvailableException)
{
break;
}
catch (Exception ex)
{
if (!cancellationToken.IsCancellationRequested)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
// We can't even start the session, wait until the process boots up again to start another metrics thread
break;
}
void StopSession()
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
// If the process has already exited, a ServerNotAvailableException will be thrown.
// This can always race with tye shutting down and a process being restarted on exiting.
catch (ServerNotAvailableException)
{
}
}
using var _ = cancellationToken.Register(() => StopSession());
try
{
var source = new EventPipeEventSource(session.EventStream);
// Distribued Tracing
HandleDistributedTracingEvents(source, processor);
// Metrics
HandleEventCounters(source, metrics);
// Logging
HandleLoggingEvents(source, loggerFactory, replicaName);
source.Process();
}
catch (DiagnosticsClientException ex)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
catch (Exception)
{
// This fails if stop is called or if the process dies
}
finally
{
session?.Dispose();
}
}
_logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", replicaName, processId);
}
public async Task ProcessEvents(int processId, CancellationToken cancellationToken)
{
var hasEventPipe = false;
for (int i = 0; i < 10; ++i)
{
if (DiagnosticsClient.GetPublishedProcesses().Contains(processId))
{
hasEventPipe = true;
break;
}
cancellationToken.ThrowIfCancellationRequested();
await Task.Delay(500);
}
if (!hasEventPipe)
{
_logger.LogInformation("Process id {PID}, does not support event pipe", processId);
return;
}
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", _dimValues[1], processId);
while (!cancellationToken.IsCancellationRequested)
{
EventPipeSession session = null;
var client = new DiagnosticsClient(processId);
try
{
session = client.StartEventPipeSession(_sourceConfig.GetProviders());
}
catch (EndOfStreamException)
{
break;
}
catch (Exception ex)
{
if (!cancellationToken.IsCancellationRequested)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
// We can't even start the session, wait until the process boots up again to start another metrics thread
break;
}
void StopSession()
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
}
using var _ = cancellationToken.Register(() => StopSession());
try
{
var source = new EventPipeEventSource(session.EventStream);
// Metrics
HandleEventCounters(source);
// Logging
HandleLoggingEvents(source);
source.Process();
}
catch (DiagnosticsClientException ex)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
catch (Exception)
{
// This fails if stop is called or if the process dies
}
finally
{
session?.Dispose();
}
}
_logger.LogInformation("Event pipe collection completed for {ServiceName} on process id {PID}", _dimValues[1], processId);
}
public void Dispose()
{
_session?.Stop();
_session?.Dispose();
}
public static async Task <int> Collect(ICollection <Action <long> > sizeChangeCallbacks, CollectTrace.Tracing tracing, FileInfo output, TraceFileFormat format = TraceFileFormat.NetTrace)
{
var processId = Process.GetCurrentProcess().Id;
var providerCollection = CreateProviderCollection();
var diagnosticsClient = new DiagnosticsClient(processId);
EventPipeSession session = null;
try
{
session = diagnosticsClient.StartEventPipeSession(providerCollection, true);
}
catch (DiagnosticsClientException e)
{
Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}");
}
if (session == null)
{
Console.Error.WriteLine("Unable to create session.");
return(ErrorCodes.SessionCreationError);
}
var failed = false;
var terminated = false;
try
{
var collectingTask = new Task(() =>
{
try
{
using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write))
{
var buffer = new byte[16 * 1024];
while (true)
{
int nBytesRead = session.EventStream.Read(buffer, 0, buffer.Length);
if (nBytesRead <= 0)
{
break;
}
fs.Write(buffer, 0, nBytesRead);
foreach (var sizeChangeCallback in sizeChangeCallbacks)
{
sizeChangeCallback(fs.Length);
}
}
}
}
catch (Exception ex)
{
failed = true;
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
}
finally
{
terminated = true;
}
});
collectingTask.Start();
tracing.Wait();
session.Stop();
await collectingTask;
//if (format != TraceFileFormat.NetTrace)
// TraceFileFormatConverter.ConvertToFormat(format, output.FullName);
return(failed ? ErrorCodes.TracingError : 0);
}
catch (Exception ex)
{
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
return(ErrorCodes.UnknownError);
}
}
private int Validate()
{
var isClean = EnsureCleanEnvironment();
if (!isClean)
{
return(-1);
}
// CollectTracing returns before EventPipe::Enable has returned, so the
// the sources we want to listen for may not have been enabled yet.
// We'll use this sentinel EventSource to check if Enable has finished
ManualResetEvent sentinelEventReceived = new ManualResetEvent(false);
var sentinelTask = new Task(() =>
{
Logger.logger.Log("Started sending sentinel events...");
while (!sentinelEventReceived.WaitOne(50))
{
SentinelEventSource.Log.SentinelEvent();
}
Logger.logger.Log("Stopped sending sentinel events");
});
sentinelTask.Start();
int processId = Process.GetCurrentProcess().Id;
object threadSync = new object(); // for locking eventpipeSession access
Func <int> optionalTraceValidationCallback = null;
DiagnosticsClient client = new DiagnosticsClient(processId);
var readerTask = new Task(() =>
{
Logger.logger.Log("Connecting to EventPipe...");
try
{
_eventPipeSession = client.StartEventPipeSession(_testProviders.Concat(_sentinelProviders));
}
catch (DiagnosticsClientException ex)
{
Logger.logger.Log("Failed to connect to EventPipe!");
Logger.logger.Log(ex.ToString());
throw new ApplicationException("Failed to connect to EventPipe");
}
using var eventPipeStream = new StreamProxy(_eventPipeSession.EventStream);
Logger.logger.Log("Creating EventPipeEventSource...");
using EventPipeEventSource source = new EventPipeEventSource(eventPipeStream);
Logger.logger.Log("EventPipeEventSource created");
source.Dynamic.All += (eventData) =>
{
try
{
if (eventData.ProviderName == "SentinelEventSource")
{
if (!sentinelEventReceived.WaitOne(0))
{
Logger.logger.Log("Saw sentinel event");
}
sentinelEventReceived.Set();
}
else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _))
{
_actualEventCounts[eventData.ProviderName]++;
}
else
{
Logger.logger.Log($"Saw new provider '{eventData.ProviderName}'");
_actualEventCounts[eventData.ProviderName] = 1;
}
}
catch (Exception e)
{
Logger.logger.Log("Exception in Dynamic.All callback " + e.ToString());
}
};
Logger.logger.Log("Dynamic.All callback registered");
if (_optionalTraceValidator != null)
{
Logger.logger.Log("Running optional trace validator");
optionalTraceValidationCallback = _optionalTraceValidator(source);
Logger.logger.Log("Finished running optional trace validator");
}
Logger.logger.Log("Starting stream processing...");
try
{
source.Process();
_droppedEvents = source.EventsLost;
}
catch (Exception)
{
Logger.logger.Log($"Exception thrown while reading; dumping culprit stream to disk...");
eventPipeStream.DumpStreamToDisk();
// rethrow it to fail the test
throw;
}
Logger.logger.Log("Stopping stream processing");
Logger.logger.Log($"Dropped {source.EventsLost} events");
});
readerTask.Start();
sentinelEventReceived.WaitOne();
Logger.logger.Log("Starting event generating action...");
_eventGeneratingAction();
Logger.logger.Log("Stopping event generating action");
// Should throw if the reader task throws any exceptions
var tokenSource = new CancellationTokenSource();
CancellationToken ct = tokenSource.Token;
readerTask.ContinueWith((task) =>
{
// if our reader task died earlier, we need to break the infinite wait below.
// We'll allow the AggregateException to be thrown and fail the test though.
Logger.logger.Log($"Task stats: isFaulted: {task.IsFaulted}, Exception == null: {task.Exception == null}");
if (task.IsFaulted || task.Exception != null)
{
tokenSource.Cancel();
}
return(task);
});
var stopTask = Task.Run(() =>
{
Logger.logger.Log("Sending StopTracing command...");
lock (threadSync) // eventpipeSession
{
_eventPipeSession.Stop();
}
Logger.logger.Log("Finished StopTracing command");
}, ct);
try
{
Task.WaitAll(new Task[] { readerTask, stopTask }, ct);
}
catch (OperationCanceledException)
{
Logger.logger.Log($"A task faulted");
Logger.logger.Log($"\treaderTask.IsFaulted = {readerTask.IsFaulted}");
if (readerTask.Exception != null)
{
throw readerTask.Exception;
}
return(-1);
}
Logger.logger.Log("Reader task finished");
Logger.logger.Log($"Dropped {_droppedEvents} events");
foreach (var(provider, expectedCount) in _expectedEventCounts)
{
if (_actualEventCounts.TryGetValue(provider, out var actualCount))
{
if (!expectedCount.Validate(actualCount))
{
return(Fail($"Event count mismatch for provider \"{provider}\": expected {expectedCount}, but saw {actualCount}"));
}
}
else
{
return(Fail($"No events for provider \"{provider}\""));
}
}
if (optionalTraceValidationCallback != null)
{
Logger.logger.Log("Validating optional callback...");
// reader thread should be dead now, no need to lock
return(optionalTraceValidationCallback());
}
else
{
return(100);
}
}
/// <summary>
/// Reports a stack trace
/// </summary>
/// <param name="ct">The cancellation token</param>
/// <param name="console"></param>
/// <param name="processId">The process to report the stack from.</param>
/// <param name="name">The name of process to report the stack from.</param>
/// <param name="output">The output path for the collected trace data.</param>
/// <param name="duration">The duration of to trace the target for. </param>
/// <returns></returns>
private static async Task <int> Report(CancellationToken ct, IConsole console, int processId, string name, TimeSpan duration)
{
string tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace";
string tempEtlxFilename = "";
try
{
// Either processName or processId has to be specified.
if (!string.IsNullOrEmpty(name))
{
if (processId != 0)
{
Console.WriteLine("Can only specify either --name or --process-id option.");
return(-1);
}
processId = CommandUtils.FindProcessIdWithName(name);
if (processId < 0)
{
return(-1);
}
}
if (processId < 0)
{
console.Error.WriteLine("Process ID should not be negative.");
return(-1);
}
else if (processId == 0)
{
console.Error.WriteLine("--process-id is required");
return(-1);
}
var client = new DiagnosticsClient(processId);
var providers = new List <EventPipeProvider>()
{
new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational)
};
// collect a *short* trace with stack samples
// the hidden '--duration' flag can increase the time of this trace in case 10ms
// is too short in a given environment, e.g., resource constrained systems
// N.B. - This trace INCLUDES rundown. For sufficiently large applications, it may take non-trivial time to collect
// the symbol data in rundown.
using (EventPipeSession session = client.StartEventPipeSession(providers))
using (FileStream fs = File.OpenWrite(tempNetTraceFilename))
{
Task copyTask = session.EventStream.CopyToAsync(fs);
await Task.Delay(duration);
session.Stop();
// check if rundown is taking more than 5 seconds and add comment to report
Task timeoutTask = Task.Delay(TimeSpan.FromSeconds(5));
Task completedTask = await Task.WhenAny(copyTask, timeoutTask);
if (completedTask == timeoutTask)
{
console.Out.WriteLine($"# Sufficiently large applications can cause this command to take non-trivial amounts of time");
}
await copyTask;
}
// using the generated trace file, symbolocate and compute stacks.
tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename);
using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null)
{
SymbolPath = SymbolPath.MicrosoftSymbolServerPath
})
using (var eventLog = new TraceLog(tempEtlxFilename))
{
var stackSource = new MutableTraceEventStackSource(eventLog)
{
OnlyManagedCodeStacks = true
};
var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader);
computer.GenerateThreadTimeStacks(stackSource);
var samplesForThread = new Dictionary <int, List <StackSourceSample> >();
stackSource.ForEach((sample) =>
{
var stackIndex = sample.StackIndex;
while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread ("))
{
stackIndex = stackSource.GetCallerIndex(stackIndex);
}
// long form for: int.Parse(threadFrame["Thread (".Length..^1)])
// Thread id is in the frame name as "Thread (<ID>)"
string template = "Thread (";
string threadFrame = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false);
int threadId = int.Parse(threadFrame.Substring(template.Length, threadFrame.Length - (template.Length + 1)));
if (samplesForThread.TryGetValue(threadId, out var samples))
{
samples.Add(sample);
}
else
{
samplesForThread[threadId] = new List <StackSourceSample>()
{
sample
};
}
});
// For every thread recorded in our trace, print the first stack
foreach (var(threadId, samples) in samplesForThread)
{
#if DEBUG
console.Out.WriteLine($"Found {samples.Count} stacks for thread 0x{threadId:X}");
#endif
PrintStack(console, threadId, samples[0], stackSource);
}
}
}
catch (Exception ex)
{
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
return(-1);
}
finally
{
if (File.Exists(tempNetTraceFilename))
{
File.Delete(tempNetTraceFilename);
}
if (File.Exists(tempEtlxFilename))
{
File.Delete(tempEtlxFilename);
}
}
return(0);
}
public static int RunTest()
{
bool success = true;
int allTypesEventCount = 0;
int arrayTypeEventCount = 0;
int emptyEventCount = 0;
int simpleEventCount = 0;
try
{
List <EventPipeProvider> providers = new List <EventPipeProvider>
{
new EventPipeProvider("MySuperAwesomeEventPipeProvider", EventLevel.Verbose)
};
using (EventPipeSession session = ProfilerControlHelpers.AttachEventPipeSessionToSelf(providers))
{
TriggerMethod();
ManualResetEvent allEventsReceivedEvent = new ManualResetEvent(false);
var source = new EventPipeEventSource(session.EventStream);
source.Dynamic.All += (TraceEvent traceEvent) =>
{
if (traceEvent.ProviderName != "MySuperAwesomeEventPipeProvider")
{
return;
}
if (traceEvent.EventName == "AllTypesEvent")
{
success &= ValidateAllTypesEvent(traceEvent);
++allTypesEventCount;
}
else if (traceEvent.EventName == "EmptyEvent")
{
success &= ValidateEmptyEvent(traceEvent);
++emptyEventCount;
}
else if (traceEvent.EventName == "SimpleEvent")
{
success &= ValidateSimpleEvent(traceEvent, simpleEventCount);
++simpleEventCount;
}
else if (traceEvent.EventName == "ArrayTypeEvent")
{
success &= ValidateArrayTypeEvent(traceEvent);
++arrayTypeEventCount;
}
if (AllEventsReceived(allTypesEventCount, arrayTypeEventCount, emptyEventCount, simpleEventCount))
{
allEventsReceivedEvent.Set();
}
};
Thread processingThread = new Thread(new ThreadStart(() =>
{
source.Process();
}));
processingThread.Start();
// The events are fired in the JITCompilationStarted callback for TriggerMethod,
// so by the time we are here, all events should be fired.
session.Stop();
allEventsReceivedEvent.WaitOne(TimeSpan.FromSeconds(90));
processingThread.Join();
}
}
catch (Exception e)
{
Console.WriteLine($"Exception {e.Message} when trying to attach");
success = false;
}
if (success && AllEventsReceived(allTypesEventCount, arrayTypeEventCount, emptyEventCount, simpleEventCount))
{
return(100);
}
else
{
Console.WriteLine("Test validation failed (EventPipeClient.exe)");
Console.WriteLine($" success={success}");
Console.WriteLine($" allTypesEventCount={allTypesEventCount} ");
Console.WriteLine($" arrayTypeEventCount={arrayTypeEventCount} ");
Console.WriteLine($" emptyEventCount={emptyEventCount}");
Console.WriteLine($" simpleEventCount={simpleEventCount}");
return(-1);
}
}
public void ProcessEvents(string applicationName,
string serviceName,
int processId,
string replicaName,
ReplicaStatus replica,
CancellationToken cancellationToken)
{
var hasEventPipe = false;
for (int i = 0; i < 10; ++i)
{
if (DiagnosticsClient.GetPublishedProcesses().Contains(processId))
{
hasEventPipe = true;
break;
}
if (cancellationToken.IsCancellationRequested)
{
return;
}
Thread.Sleep(500);
}
if (!hasEventPipe)
{
_logger.LogInformation("Process id {PID}, does not support event pipe", processId);
return;
}
_logger.LogInformation("Listening for event pipe events for {ServiceName} on process id {PID}", replicaName, processId);
// Create the logger factory for this replica
using var loggerFactory = LoggerFactory.Create(builder => ConfigureLogging(serviceName, replicaName, builder));
var processor = new SimpleSpanProcessor(CreateSpanExporter(serviceName, replicaName));
var providers = new List <EventPipeProvider>()
{
// Runtime Metrics
new EventPipeProvider(
SystemRuntimeEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
MicrosoftAspNetCoreHostingEventSourceName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
new EventPipeProvider(
GrpcAspNetCoreServer,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Application Metrics
new EventPipeProvider(
applicationName,
EventLevel.Informational,
(long)ClrTraceEventParser.Keywords.None,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// Logging
new EventPipeProvider(
MicrosoftExtensionsLoggingProviderName,
EventLevel.LogAlways,
(long)(LoggingEventSource.Keywords.JsonMessage | LoggingEventSource.Keywords.FormattedMessage)
),
// Distributed Tracing
// Activity correlation
new EventPipeProvider(TplEventSource,
keywords: 0x80,
eventLevel: EventLevel.LogAlways),
// Diagnostic source events
new EventPipeProvider(DiagnosticSourceEventSource,
keywords: 0x1 | 0x2,
eventLevel: EventLevel.Verbose,
arguments: new Dictionary <string, string>
{
{ "FilterAndPayloadSpecs", DiagnosticFilterString }
})
};
while (!cancellationToken.IsCancellationRequested)
{
EventPipeSession session = null;
var client = new DiagnosticsClient(processId);
try
{
session = client.StartEventPipeSession(providers);
}
catch (EndOfStreamException)
{
break;
}
catch (Exception ex)
{
if (!cancellationToken.IsCancellationRequested)
{
_logger.LogDebug(0, ex, "Failed to start the event pipe session");
}
// We can't even start the session, wait until the process boots up again to start another metrics thread
break;
}
void StopSession()
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
}
using var _ = cancellationToken.Register(() => StopSession());
try
{
var source = new EventPipeEventSource(session.EventStream);
var activities = new Dictionary <string, ActivityItem>();
source.Dynamic.All += traceEvent =>
{
try
{
// Uncomment to debug the diagnostics source event source
//if (traceEvent.EventName == "Message")
//{
// _logger.LogTrace("[" + replicaName + "]:" + traceEvent.PayloadValue(0));
//}
//// Distributed tracing
// else
if (traceEvent.EventName == "Activity1Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments)
{
string activityId = null;
string parentId = null;
string operationName = null;
string httpMethod = null;
string path = null;
string spanId = null;
string parentSpanId = null;
string traceId = null;
DateTime startTime = default;
ActivityIdFormat idFormat = default;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "ActivityParentId")
{
parentId = value;
}
else if (key == "ActivityOperationName")
{
operationName = value;
}
else if (key == "ActivitySpanId")
{
spanId = value;
}
else if (key == "ActivityTraceId")
{
traceId = value;
}
else if (key == "ActivityParentSpanId")
{
parentSpanId = value;
}
else if (key == "Method")
{
httpMethod = value;
}
else if (key == "Path")
{
path = value;
}
else if (key == "ActivityStartTime")
{
startTime = new DateTime(long.Parse(value), DateTimeKind.Utc);
}
else if (key == "ActivityIdFormat")
{
idFormat = Enum.Parse <ActivityIdFormat>(value);
}
}
if (string.IsNullOrEmpty(activityId))
{
// Not a 3.1 application (we can detect this earlier)
return;
}
if (idFormat == ActivityIdFormat.Hierarchical)
{
// We need W3C to make it work
return;
}
// This is what open telemetry currently does
// https://github.com/open-telemetry/opentelemetry-dotnet/blob/4ba732af062ddc2759c02aebbc91335aaa3f7173/src/OpenTelemetry.Collector.AspNetCore/Implementation/HttpInListener.cs#L65-L92
var item = new ActivityItem()
{
Name = path,
SpanId = ActivitySpanId.CreateFromString(spanId),
TraceId = ActivityTraceId.CreateFromString(traceId),
ParentSpanId = parentSpanId == "0000000000000000" ? default : ActivitySpanId.CreateFromString(parentSpanId),
StartTime = startTime,
};
item.Attributes[SpanAttributeConstants.HttpMethodKey] = httpMethod;
item.Attributes[SpanAttributeConstants.HttpPathKey] = path;
activities[activityId] = item;
}
}
else if (traceEvent.EventName == "Activity1Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
if (traceEvent.PayloadByName("Arguments") is IDictionary <string, object>[] arguments)
{
string activityId = null;
TimeSpan duration = default;
int statusCode = 0;
foreach (var arg in arguments)
{
var key = (string)arg["Key"];
var value = (string)arg["Value"];
if (key == "ActivityId")
{
activityId = value;
}
else if (key == "StatusCode")
{
statusCode = int.Parse(value);
}
else if (key == "ActivityDuration")
{
duration = new TimeSpan(long.Parse(value));
}
}
if (string.IsNullOrEmpty(activityId))
{
// Not a 3.1 application (we can detect this earlier)
return;
}
if (activities.TryGetValue(activityId, out var item))
{
item.Attributes[SpanAttributeConstants.HttpStatusCodeKey] = statusCode;
item.EndTime = item.StartTime + duration;
var spanData = new SpanData(item.Name,
new SpanContext(item.TraceId, item.SpanId, ActivityTraceFlags.Recorded),
item.ParentSpanId,
SpanKind.Server,
item.StartTime,
item.Attributes,
Enumerable.Empty <Event>(),
Enumerable.Empty <Link>(),
null,
Status.Ok,
item.EndTime);
processor.OnEnd(spanData);
activities.Remove(activityId);
}
}
}
else if (traceEvent.EventName == "Activity2Start/Start")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
_logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired");
}
else if (traceEvent.EventName == "Activity2Stop/Stop")
{
var listenerEventName = (string)traceEvent.PayloadByName("EventName");
_logger.LogDebug("[" + replicaName + "]: " + listenerEventName + " fired");
}
// Metrics
else if (traceEvent.EventName.Equals("EventCounters"))
{
var payloadVal = (IDictionary <string, object>)traceEvent.PayloadValue(0);
var eventPayload = (IDictionary <string, object>)payloadVal["Payload"];
ICounterPayload payload = CounterPayload.FromPayload(eventPayload);
replica.Metrics[traceEvent.ProviderName + "/" + payload.Name] = payload.Value;
}
}
catch (Exception ex)
{
_logger.LogError(ex, "Error processing counter for {ProviderName}:{EventName}", traceEvent.ProviderName, traceEvent.EventName);
}
};
// Logging
string lastFormattedMessage = "";
var logActivities = new Dictionary <Guid, LogActivityItem>();
var stack = new Stack <Guid>();
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStart/Start", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// TODO: Store this information by logger factory id
var item = new LogActivityItem
{
ActivityID = traceEvent.ActivityID,
ScopedObject = new LogObject(JsonDocument.Parse(argsJson).RootElement),
};
if (stack.TryPeek(out var parentId) && logActivities.TryGetValue(parentId, out var parentItem))
{
item.Parent = parentItem;
}
stack.Push(traceEvent.ActivityID);
logActivities[traceEvent.ActivityID] = item;
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "ActivityJsonStop/Stop", (traceEvent) =>
{
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
stack.Pop();
logActivities.Remove(traceEvent.ActivityID);
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "MessageJson", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, ExceptionJson, ArgumentsJson
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var exceptionJson = (string)traceEvent.PayloadByName("ExceptionJson");
var argsJson = (string)traceEvent.PayloadByName("ArgumentsJson");
// There's a bug that causes some of the columns to get mixed up
if (eventName.StartsWith("{"))
{
argsJson = exceptionJson;
exceptionJson = eventName;
eventName = null;
}
if (string.IsNullOrEmpty(argsJson))
{
return;
}
Exception exception = null;
var logger = loggerFactory.CreateLogger(categoryName);
var scopes = new List <IDisposable>();
if (logActivities.TryGetValue(traceEvent.ActivityID, out var logActivityItem))
{
// REVIEW: Does order matter here? We're combining everything anyways.
while (logActivityItem != null)
{
scopes.Add(logger.BeginScope(logActivityItem.ScopedObject));
logActivityItem = logActivityItem.Parent;
}
}
try
{
if (exceptionJson != "{}")
{
var exceptionMessage = JsonSerializer.Deserialize <JsonElement>(exceptionJson);
exception = new LoggerException(exceptionMessage);
}
var message = JsonSerializer.Deserialize <JsonElement>(argsJson);
if (message.TryGetProperty("{OriginalFormat}", out var formatElement))
{
var formatString = formatElement.GetString();
var formatter = new LogValuesFormatter(formatString);
object[] args = new object[formatter.ValueNames.Count];
for (int i = 0; i < args.Length; i++)
{
args[i] = message.GetProperty(formatter.ValueNames[i]).GetString();
}
logger.Log(logLevel, new EventId(eventId, eventName), exception, formatString, args);
}
else
{
var obj = new LogObject(message, lastFormattedMessage);
logger.Log(logLevel, new EventId(eventId, eventName), obj, exception, LogObject.Callback);
}
}
catch (Exception ex)
{
_logger.LogDebug(ex, "Error processing log entry for {ServiceName}", replicaName);
}
finally
{
scopes.ForEach(d => d.Dispose());
}
});
source.Dynamic.AddCallbackForProviderEvent(MicrosoftExtensionsLoggingProviderName, "FormattedMessage", (traceEvent) =>
{
// Level, FactoryID, LoggerName, EventID, EventName, FormattedMessage
var logLevel = (LogLevel)traceEvent.PayloadByName("Level");
var factoryId = (int)traceEvent.PayloadByName("FactoryID");
var categoryName = (string)traceEvent.PayloadByName("LoggerName");
var eventId = (int)traceEvent.PayloadByName("EventId");
var eventName = (string)traceEvent.PayloadByName("EventName");
var formattedMessage = (string)traceEvent.PayloadByName("FormattedMessage");
if (string.IsNullOrEmpty(formattedMessage))
{
formattedMessage = eventName;
eventName = "";
}
lastFormattedMessage = formattedMessage;
});
source.Process();
}
private async Task StartTracing(Action <string> log)
{
var providers = new List <EventPipeProvider>()
{
// Runtime Metrics
new EventPipeProvider(
"System.Runtime",
EventLevel.Informational,
0,
new Dictionary <string, string>()
{
{ "EventCounterIntervalSec", "1" }
}
),
// new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational),
new EventPipeProvider("Microsoft-Windows-DotNETRuntime", EventLevel.Informational, 65536 | 32768),//ClrTraceEventParser.Keywords.Default)
// Activity correlation
new EventPipeProvider("System.Threading.Tasks.TplEventSource",
keywords: 511,
eventLevel: EventLevel.LogAlways),
};
log($"Starting event pipe session for pid {Process.GetCurrentProcess().Id}");
EventPipeSession session = null;
var client = new DiagnosticsClient(Process.GetCurrentProcess().Id);
try
{
session = client.StartEventPipeSession(providers);
}
catch (EndOfStreamException)
{
}
// If the process has already exited, a ServerNotAvailableException will be thrown.
catch (ServerNotAvailableException)
{
}
catch (Exception)
{
// We can't even start the session, wait until the process boots up again to start another metrics thread
}
void StopSession()
{
try
{
session.Stop();
}
catch (EndOfStreamException)
{
// If the app we're monitoring exits abruptly, this may throw in which case we just swallow the exception and exit gracefully.
}
// We may time out if the process ended before we sent StopTracing command. We can just exit in that case.
catch (TimeoutException)
{
}
// On Unix platforms, we may actually get a PNSE since the pipe is gone with the process, and Runtime Client Library
// does not know how to distinguish a situation where there is no pipe to begin with, or where the process has exited
// before dotnet-counters and got rid of a pipe that once existed.
// Since we are catching this in StopMonitor() we know that the pipe once existed (otherwise the exception would've
// been thrown in StartMonitor directly)
catch (PlatformNotSupportedException)
{
}
// If the process has already exited, a ServerNotAvailableException will be thrown.
// This can always race with tye shutting down and a process being restarted on exiting.
catch (ServerNotAvailableException)
{
}
}
var _ = _cts.Token.Register(() => StopSession());
try
{
using var traceOutput = File.Create("trace.nettrace");
await session.EventStream.CopyToAsync(traceOutput);
}
catch (DiagnosticsClientException)
{
}
catch (Exception)
{
// This fails if stop is called or if the process dies
}
finally
{
session?.Dispose();
}
}
static async Task <int> Main(string[] args)
{
if (args.Length == 0 || args.Length > 1 || (args.Length == 1 && _helpFlags.Contains(args[0])))
{
PrintUsage();
return(-1);
}
var pid = int.Parse(args[0]);
var tempNetTraceFilename = Path.GetRandomFileName() + ".nettrace";
var tempEtlxFilename = "";
try
{
var client = new DiagnosticsClient(pid);
var providers = new List <EventPipeProvider>()
{
new EventPipeProvider("Microsoft-DotNETCore-SampleProfiler", EventLevel.Informational)
};
using (EventPipeSession session = client.StartEventPipeSession(providers))
using (FileStream fs = File.OpenWrite(tempNetTraceFilename))
{
Task copyTask = session.EventStream.CopyToAsync(fs);
await Task.Delay(10);
session.Stop();
await copyTask;
}
tempEtlxFilename = TraceLog.CreateFromEventPipeDataFile(tempNetTraceFilename);
using (var symbolReader = new SymbolReader(System.IO.TextWriter.Null)
{
SymbolPath = SymbolPath.MicrosoftSymbolServerPath
})
using (var eventLog = new TraceLog(tempEtlxFilename))
{
var stackSource = new MutableTraceEventStackSource(eventLog)
{
OnlyManagedCodeStacks = true
};
var computer = new SampleProfilerThreadTimeComputer(eventLog, symbolReader);
computer.GenerateThreadTimeStacks(stackSource);
var samplesForThread = new Dictionary <string, List <StackSourceSample> >();
stackSource.ForEach((sample) =>
{
var stackIndex = sample.StackIndex;
while (!stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false).StartsWith("Thread ("))
{
stackIndex = stackSource.GetCallerIndex(stackIndex);
}
var threadName = stackSource.GetFrameName(stackSource.GetFrameIndex(stackIndex), false);
if (samplesForThread.TryGetValue(threadName, out var samples))
{
samples.Add(sample);
}
else
{
samplesForThread[threadName] = new List <StackSourceSample>()
{
sample
};
}
});
foreach (var(threadName, samples) in samplesForThread)
{
#if DEBUG
Console.WriteLine($"Found {samples.Count} stacks for thread {threadName}");
#endif
PrintStack(threadName, samples[0], stackSource);
}
}
return(0);
}
catch (System.Exception e)
{
Console.WriteLine(e);
return(-1);
}
finally
{
if (File.Exists(tempNetTraceFilename))
{
File.Delete(tempNetTraceFilename);
}
if (File.Exists(tempEtlxFilename))
{
File.Delete(tempEtlxFilename);
}
}
}
/// <summary>
/// Collects a diagnostic trace from a currently running process.
/// </summary>
/// <param name="ct">The cancellation token</param>
/// <param name="console"></param>
/// <param name="processId">The process to collect the trace from.</param>
/// <param name="name">The name of process to collect the trace from.</param>
/// <param name="output">The output path for the collected trace data.</param>
/// <param name="buffersize">Sets the size of the in-memory circular buffer in megabytes.</param>
/// <param name="providers">A list of EventPipe providers to be enabled. This is in the form 'Provider[,Provider]', where Provider is in the form: 'KnownProviderName[:Flags[:Level][:KeyValueArgs]]', and KeyValueArgs is in the form: '[key1=value1][;key2=value2]'</param>
/// <param name="profile">A named pre-defined set of provider configurations that allows common tracing scenarios to be specified succinctly.</param>
/// <param name="format">The desired format of the created trace file.</param>
/// <param name="duration">The duration of trace to be taken. </param>
/// <param name="clrevents">A list of CLR events to be emitted.</param>
/// <param name="clreventlevel">The verbosity level of CLR events</param>
/// <returns></returns>
private static async Task <int> Collect(CancellationToken ct, IConsole console, int processId, FileInfo output, uint buffersize, string providers, string profile, TraceFileFormat format, TimeSpan duration, string clrevents, string clreventlevel, string name)
{
try
{
Debug.Assert(output != null);
Debug.Assert(profile != null);
// Either processName or processId has to be specified.
if (name != null)
{
if (processId != 0)
{
Console.WriteLine("Can only specify either --name or --process-id option.");
return(ErrorCodes.ArgumentError);
}
processId = CommandUtils.FindProcessIdWithName(name);
if (processId < 0)
{
return(ErrorCodes.ArgumentError);
}
}
if (processId < 0)
{
Console.Error.WriteLine("Process ID should not be negative.");
return(ErrorCodes.ArgumentError);
}
else if (processId == 0)
{
Console.Error.WriteLine("--process-id is required");
return(ErrorCodes.ArgumentError);
}
if (profile.Length == 0 && providers.Length == 0 && clrevents.Length == 0)
{
Console.Out.WriteLine("No profile or providers specified, defaulting to trace profile 'cpu-sampling'");
profile = "cpu-sampling";
}
Dictionary <string, string> enabledBy = new Dictionary <string, string>();
var providerCollection = Extensions.ToProviders(providers);
foreach (EventPipeProvider providerCollectionProvider in providerCollection)
{
enabledBy[providerCollectionProvider.Name] = "--providers ";
}
if (profile.Length != 0)
{
var selectedProfile = ListProfilesCommandHandler.DotNETRuntimeProfiles
.FirstOrDefault(p => p.Name.Equals(profile, StringComparison.OrdinalIgnoreCase));
if (selectedProfile == null)
{
Console.Error.WriteLine($"Invalid profile name: {profile}");
return(ErrorCodes.ArgumentError);
}
Profile.MergeProfileAndProviders(selectedProfile, providerCollection, enabledBy);
}
// Parse --clrevents parameter
if (clrevents.Length != 0)
{
// Ignore --clrevents if CLR event provider was already specified via --profile or --providers command.
if (enabledBy.ContainsKey(Extensions.CLREventProviderName))
{
Console.WriteLine($"The argument --clrevents {clrevents} will be ignored because the CLR provider was configured via either --profile or --providers command.");
}
else
{
var clrProvider = Extensions.ToCLREventPipeProvider(clrevents, clreventlevel);
providerCollection.Add(clrProvider);
enabledBy[Extensions.CLREventProviderName] = "--clrevents";
}
}
if (providerCollection.Count <= 0)
{
Console.Error.WriteLine("No providers were specified to start a trace.");
return(ErrorCodes.ArgumentError);
}
PrintProviders(providerCollection, enabledBy);
var process = Process.GetProcessById(processId);
var shouldExit = new ManualResetEvent(false);
var shouldStopAfterDuration = duration != default(TimeSpan);
var rundownRequested = false;
System.Timers.Timer durationTimer = null;
ct.Register(() => shouldExit.Set());
var diagnosticsClient = new DiagnosticsClient(processId);
using (VirtualTerminalMode vTermMode = VirtualTerminalMode.TryEnable())
{
EventPipeSession session = null;
try
{
session = diagnosticsClient.StartEventPipeSession(providerCollection, true, (int)buffersize);
}
catch (DiagnosticsClientException e)
{
Console.Error.WriteLine($"Unable to start a tracing session: {e.ToString()}");
}
if (session == null)
{
Console.Error.WriteLine("Unable to create session.");
return(ErrorCodes.SessionCreationError);
}
if (shouldStopAfterDuration)
{
durationTimer = new System.Timers.Timer(duration.TotalMilliseconds);
durationTimer.Elapsed += (s, e) => shouldExit.Set();
durationTimer.AutoReset = false;
}
var stopwatch = new Stopwatch();
durationTimer?.Start();
stopwatch.Start();
LineRewriter rewriter = null;
using (var fs = new FileStream(output.FullName, FileMode.Create, FileAccess.Write))
{
Console.Out.WriteLine($"Process : {process.MainModule.FileName}");
Console.Out.WriteLine($"Output File : {fs.Name}");
if (shouldStopAfterDuration)
{
Console.Out.WriteLine($"Trace Duration : {duration.ToString(@"dd\:hh\:mm\:ss")}");
}
Console.Out.WriteLine("\n\n");
var fileInfo = new FileInfo(output.FullName);
Task copyTask = session.EventStream.CopyToAsync(fs);
if (!Console.IsOutputRedirected)
{
rewriter = new LineRewriter {
LineToClear = Console.CursorTop - 1
};
Console.CursorVisible = false;
}
Action printStatus = () =>
{
if (!Console.IsOutputRedirected)
{
rewriter?.RewriteConsoleLine();
}
fileInfo.Refresh();
Console.Out.WriteLine($"[{stopwatch.Elapsed.ToString(@"dd\:hh\:mm\:ss")}]\tRecording trace {GetSize(fileInfo.Length)}");
Console.Out.WriteLine("Press <Enter> or <Ctrl+C> to exit...");
if (rundownRequested)
{
Console.Out.WriteLine("Stopping the trace. This may take up to minutes depending on the application being traced.");
}
};
while (!shouldExit.WaitOne(100) && !(!Console.IsInputRedirected && Console.KeyAvailable && Console.ReadKey(true).Key == ConsoleKey.Enter))
{
printStatus();
}
// Behavior concerning Enter moving text in the terminal buffer when at the bottom of the buffer
// is different between Console/Terminals on Windows and Mac/Linux
if (!RuntimeInformation.IsOSPlatform(OSPlatform.Windows) &&
!Console.IsOutputRedirected &&
rewriter != null &&
Math.Abs(Console.CursorTop - Console.BufferHeight) == 1)
{
rewriter.LineToClear--;
}
durationTimer?.Stop();
rundownRequested = true;
session.Stop();
do
{
printStatus();
} while (!copyTask.Wait(100));
}
Console.Out.WriteLine("\nTrace completed.");
if (format != TraceFileFormat.NetTrace)
{
TraceFileFormatConverter.ConvertToFormat(format, output.FullName);
}
}
}
catch (Exception ex)
{
Console.Error.WriteLine($"[ERROR] {ex.ToString()}");
return(ErrorCodes.TracingError);
}
finally
{
if (console.GetTerminal() != null)
{
Console.CursorVisible = true;
}
}
return(await Task.FromResult(0));
}
private int Validate()
{
// FIXME: This is a bandaid fix for a deadlock in EventPipeEventSource caused by
// the lazy caching in the Regex library. The caching creates a ConcurrentDictionary
// and because it is the first one in the process, it creates an EventSource which
// results in a deadlock over a lock in EventPipe. These lines should be removed once the
// underlying issue is fixed by forcing these events to try to be written _before_ we shutdown.
//
// see: https://github.com/dotnet/runtime/pull/1794 for details on the issue
//
var emptyConcurrentDictionary = new ConcurrentDictionary <string, string>();
emptyConcurrentDictionary["foo"] = "bar";
var __count = emptyConcurrentDictionary.Count;
var isClean = IpcTraceTest.EnsureCleanEnvironment();
if (!isClean)
{
return(-1);
}
// CollectTracing returns before EventPipe::Enable has returned, so the
// the sources we want to listen for may not have been enabled yet.
// We'll use this sentinel EventSource to check if Enable has finished
ManualResetEvent sentinelEventReceived = new ManualResetEvent(false);
var sentinelTask = new Task(() =>
{
Logger.logger.Log("Started sending sentinel events...");
while (!sentinelEventReceived.WaitOne(50))
{
SentinelEventSource.Log.SentinelEvent();
}
Logger.logger.Log("Stopped sending sentinel events");
});
sentinelTask.Start();
int processId = Process.GetCurrentProcess().Id;
object threadSync = new object(); // for locking eventpipeSession access
Func <int> optionalTraceValidationCallback = null;
DiagnosticsClient client = new DiagnosticsClient(processId);
#if DIAGNOSTICS_RUNTIME
if (OperatingSystem.IsAndroid())
{
client = new DiagnosticsClient(new IpcEndpointConfig("127.0.0.1:9000", IpcEndpointConfig.TransportType.TcpSocket, IpcEndpointConfig.PortType.Listen));
}
#endif
var readerTask = new Task(() =>
{
Logger.logger.Log("Connecting to EventPipe...");
try
{
_eventPipeSession = client.StartEventPipeSession(_testProviders.Concat(_sentinelProviders));
}
catch (DiagnosticsClientException ex)
{
Logger.logger.Log("Failed to connect to EventPipe!");
Logger.logger.Log(ex.ToString());
throw new ApplicationException("Failed to connect to EventPipe");
}
using (var eventPipeStream = new StreamProxy(_eventPipeSession.EventStream))
{
Logger.logger.Log("Creating EventPipeEventSource...");
using (EventPipeEventSource source = new EventPipeEventSource(eventPipeStream))
{
Logger.logger.Log("EventPipeEventSource created");
source.Dynamic.All += (eventData) =>
{
try
{
if (eventData.ProviderName == "SentinelEventSource")
{
if (!sentinelEventReceived.WaitOne(0))
{
Logger.logger.Log("Saw sentinel event");
}
sentinelEventReceived.Set();
}
else if (_actualEventCounts.TryGetValue(eventData.ProviderName, out _))
{
_actualEventCounts[eventData.ProviderName]++;
}
else
{
Logger.logger.Log($"Saw new provider '{eventData.ProviderName}'");
_actualEventCounts[eventData.ProviderName] = 1;
}
}
catch (Exception e)
{
Logger.logger.Log("Exception in Dynamic.All callback " + e.ToString());
}
};
Logger.logger.Log("Dynamic.All callback registered");
if (_optionalTraceValidator != null)
{
Logger.logger.Log("Running optional trace validator");
optionalTraceValidationCallback = _optionalTraceValidator(source);
Logger.logger.Log("Finished running optional trace validator");
}
Logger.logger.Log("Starting stream processing...");
try
{
source.Process();
}
catch (Exception)
{
Logger.logger.Log($"Exception thrown while reading; dumping culprit stream to disk...");
eventPipeStream.DumpStreamToDisk();
// rethrow it to fail the test
throw;
}
Logger.logger.Log("Stopping stream processing");
Logger.logger.Log($"Dropped {source.EventsLost} events");
}
}
});
var waitSentinelEventTask = new Task(() => {
sentinelEventReceived.WaitOne();
});
readerTask.Start();
waitSentinelEventTask.Start();
// Will throw if the reader task throws any exceptions before signaling sentinelEventReceived.
Task.WaitAny(readerTask, waitSentinelEventTask);
Logger.logger.Log("Starting event generating action...");
_eventGeneratingAction();
Logger.logger.Log("Stopping event generating action");
var stopTask = Task.Run(() =>
{
Logger.logger.Log("Sending StopTracing command...");
lock (threadSync) // eventpipeSession
{
_eventPipeSession.Stop();
}
Logger.logger.Log("Finished StopTracing command");
});
// Should throw if the reader task throws any exceptions
Task.WaitAll(readerTask, stopTask);
Logger.logger.Log("Reader task finished");
foreach (var(provider, expectedCount) in _expectedEventCounts)
{
if (_actualEventCounts.TryGetValue(provider, out var actualCount))
{
if (!expectedCount.Validate(actualCount))
{
return(Fail($"Event count mismatch for provider \"{provider}\": expected {expectedCount}, but saw {actualCount}"));
}
}
else
{
return(Fail($"No events for provider \"{provider}\""));
}
}
if (optionalTraceValidationCallback != null)
{
Logger.logger.Log("Validating optional callback...");
// reader thread should be dead now, no need to lock
return(optionalTraceValidationCallback());
}
else
{
return(100);
}
}