diff --git a/src/shared/Atlassian.Bitbucket.UI.Avalonia/Program.cs b/src/shared/Atlassian.Bitbucket.UI.Avalonia/Program.cs index b715486e3..8bc3a6571 100644 --- a/src/shared/Atlassian.Bitbucket.UI.Avalonia/Program.cs +++ b/src/shared/Atlassian.Bitbucket.UI.Avalonia/Program.cs @@ -47,7 +47,7 @@ private static void AppMain(object o) // Set the session id (sid) for the helper process, to be // used when TRACE2 tracing is enabled. - SidManager.CreateSid(); + ProcessManager.CreateSid(); using (var context = new CommandContext()) using (var app = new HelperApplication(context)) { diff --git a/src/shared/Core.Tests/ProcessManagerTests.cs b/src/shared/Core.Tests/ProcessManagerTests.cs new file mode 100644 index 000000000..8e96c41f0 --- /dev/null +++ b/src/shared/Core.Tests/ProcessManagerTests.cs @@ -0,0 +1,33 @@ +using GitCredentialManager; +using Xunit; + +namespace Core.Tests; + +public class ProcessManagerTests +{ + [Theory] + [InlineData("", 0)] + [InlineData("foo", 0)] + [InlineData("foo/bar", 1)] + [InlineData("foo/bar/baz", 2)] + public void CreateSid_Envar_Returns_Expected_Sid(string input, int expected) + { + ProcessManager.Sid = input; + var actual = ProcessManager.GetProcessDepth(); + + Assert.Equal(expected, actual); + } + + [Theory] + [InlineData("", 0)] + [InlineData("foo", 0)] + [InlineData("foo/bar", 1)] + [InlineData("foo/bar/baz", 2)] + public void TryGetProcessDepth_Returns_Expected_Depth(string input, int expected) + { + ProcessManager.Sid = input; + var actual = ProcessManager.GetProcessDepth(); + + Assert.Equal(expected, actual); + } +} \ No newline at end of file diff --git a/src/shared/Core.Tests/Trace2Tests.cs b/src/shared/Core.Tests/Trace2Tests.cs index 9816a0d3e..445c177e2 100644 --- a/src/shared/Core.Tests/Trace2Tests.cs +++ b/src/shared/Core.Tests/Trace2Tests.cs @@ -1,6 +1,3 @@ -using System; -using System.Text.RegularExpressions; -using GitCredentialManager.Tests.Objects; using Xunit; namespace GitCredentialManager.Tests; @@ -30,4 +27,14 @@ public void TryGetPipeName_Windows_Returns_Expected_Value(string input, string e Assert.True(isSuccessful); Assert.Matches(actual, expected); } + + [Theory] + [InlineData(0.013772, " 0.013772 ")] + [InlineData(26.316083, " 26.316083 ")] + [InlineData(100.316083, "100.316083 ")] + public void BuildTimeSpan_Match_Returns_Expected_String(double input, string expected) + { + var actual = Trace2Message.BuildTimeSpan(input); + Assert.Equal(expected, actual); + } } diff --git a/src/shared/Core/Constants.cs b/src/shared/Core/Constants.cs index 617aed645..e5f283b47 100644 --- a/src/shared/Core/Constants.cs +++ b/src/shared/Core/Constants.cs @@ -56,6 +56,7 @@ public static class EnvironmentVariables public const string GcmAllowWia = "GCM_ALLOW_WINDOWSAUTH"; public const string GitTrace2Event = "GIT_TRACE2_EVENT"; public const string GitTrace2Normal = "GIT_TRACE2"; + public const string GitTrace2Performance = "GIT_TRACE2_PERF"; /* * Unlike other environment variables, these proxy variables are normally lowercase only. @@ -169,9 +170,10 @@ public static class Remote public static class Trace2 { - public const string SectionName = "trace2"; - public const string EventTarget = "eventtarget"; - public const string NormalTarget = "normaltarget"; + public const string SectionName = "trace2"; + public const string EventTarget = "eventtarget"; + public const string NormalTarget = "normaltarget"; + public const string PerformanceTarget = "perftarget"; } } diff --git a/src/shared/Core/ITrace2Writer.cs b/src/shared/Core/ITrace2Writer.cs index 6dd302add..426c69f1e 100644 --- a/src/shared/Core/ITrace2Writer.cs +++ b/src/shared/Core/ITrace2Writer.cs @@ -3,6 +3,17 @@ namespace GitCredentialManager; +/// +/// The different format targets supported in the TRACE2 tracing +/// system. +/// +public enum Trace2FormatTarget +{ + Event, + Normal, + Performance +} + public interface ITrace2Writer : IDisposable { bool Failed { get; } @@ -34,6 +45,9 @@ protected string Format(Trace2Message message) case Trace2FormatTarget.Normal: sb.Append(message.ToNormalString()); break; + case Trace2FormatTarget.Performance: + sb.Append(message.ToPerformanceString()); + break; default: Console.WriteLine($"warning: unrecognized format target '{_formatTarget}', disabling TRACE2 tracing."); Failed = true; diff --git a/src/shared/Core/ProcessManager.cs b/src/shared/Core/ProcessManager.cs index 78b0e2c9c..8f0e542ad 100644 --- a/src/shared/Core/ProcessManager.cs +++ b/src/shared/Core/ProcessManager.cs @@ -1,3 +1,4 @@ +using System; using System.Diagnostics; using System.Threading.Tasks; @@ -27,8 +28,14 @@ public interface IProcessManager public class ProcessManager : IProcessManager { + private const string SidEnvar = "GIT_TRACE2_PARENT_SID"; + protected readonly ITrace2 Trace2; + public static string Sid { get; internal set; } + + public static int Depth { get; internal set; } + public ProcessManager(ITrace2 trace2) { EnsureArgument.NotNull(trace2, nameof(trace2)); @@ -50,9 +57,51 @@ public virtual ChildProcess CreateProcess(string path, string args, bool useShel return CreateProcess(psi); } - public virtual ChildProcess CreateProcess(ProcessStartInfo psi) { return new ChildProcess(Trace2, psi); } + + /// + /// Create a TRACE2 "session id" (sid) for this process. + /// + public static void CreateSid() + { + Sid = Environment.GetEnvironmentVariable(SidEnvar); + + if (!string.IsNullOrEmpty(Sid)) + { + // Use trim to ensure no accidental leading or trailing slashes + Sid = $"{Sid.Trim('/')}/{Guid.NewGuid():D}"; + // Only check for process depth if there is a parent. + // If there is not a parent, depth defaults to 0. + Depth = GetProcessDepth(); + } + else + { + // We are the root process; create our own 'root' SID + Sid = Guid.NewGuid().ToString("D"); + } + + Environment.SetEnvironmentVariable(SidEnvar, Sid); + } + + /// + /// Get "depth" of current process relative to top-level GCM process. + /// + /// Depth of current process. + internal static int GetProcessDepth() + { + char processSeparator = '/'; + + int count = 0; + // Use AsSpan() for slight performance bump over traditional foreach loop. + foreach (var c in Sid.AsSpan()) + { + if (c == processSeparator) + count++; + } + + return count; + } } diff --git a/src/shared/Core/Settings.cs b/src/shared/Core/Settings.cs index 55069d63b..79935f957 100644 --- a/src/shared/Core/Settings.cs +++ b/src/shared/Core/Settings.cs @@ -533,6 +533,12 @@ public Trace2Settings GetTrace2Settings() settings.FormatTargetsAndValues.Add(Trace2FormatTarget.Normal, value); } + if (TryGetSetting(Constants.EnvironmentVariables.GitTrace2Performance, KnownGitCfg.Trace2.SectionName, + Constants.GitConfiguration.Trace2.PerformanceTarget, out value)) + { + settings.FormatTargetsAndValues.Add(Trace2FormatTarget.Performance, value); + } + return settings; } diff --git a/src/shared/Core/SidManager.cs b/src/shared/Core/SidManager.cs deleted file mode 100644 index 6ccfb72ed..000000000 --- a/src/shared/Core/SidManager.cs +++ /dev/null @@ -1,27 +0,0 @@ -using System; - -namespace GitCredentialManager; - -public class SidManager -{ - private const string SidEnvar = "GIT_TRACE2_PARENT_SID"; - - public static string Sid { get; private set; } - - public static void CreateSid() - { - Sid = Environment.GetEnvironmentVariable(SidEnvar); - - if (!string.IsNullOrEmpty(Sid)) - { - Sid = $"{Sid}/{Guid.NewGuid():D}"; - } - else - { - // We are the root process; create our own 'root' SID - Sid = Guid.NewGuid().ToString("D"); - } - - Environment.SetEnvironmentVariable(SidEnvar, Sid); - } -} diff --git a/src/shared/Core/Trace2.cs b/src/shared/Core/Trace2.cs index 7ba44d3d2..813ebbf3b 100644 --- a/src/shared/Core/Trace2.cs +++ b/src/shared/Core/Trace2.cs @@ -1,10 +1,8 @@ using System; -using System.Collections; using System.Collections.Generic; +using System.ComponentModel; using System.IO; using System.IO.Pipes; -using System.Linq; -using System.Runtime.Serialization; using System.Text; using Newtonsoft.Json; using Newtonsoft.Json.Converters; @@ -42,6 +40,15 @@ public class Trace2Settings new Dictionary(); } +public class PerformanceFormatSpan +{ + public int Size { get; set; } + + public int BeginPadding { get; set; } + + public int EndPadding { get; set; } +} + /// /// Represents the application's TRACE2 tracing system. /// @@ -146,7 +153,7 @@ public void Initialize(DateTimeOffset startTime) _applicationStartTime = startTime; _settings = _commandContext.Settings.GetTrace2Settings(); - _sid = SidManager.Sid; + _sid = ProcessManager.Sid; InitializeWriters(); @@ -212,7 +219,8 @@ public void WriteChildStart(DateTimeOffset startTime, Id = ++_childProcCounter, Classification = processClass, UseShell = useShell, - Argv = procArgs + Argv = procArgs, + Depth = ProcessManager.Depth }); } @@ -242,7 +250,8 @@ public void WriteChildExit( Id = _childProcCounter, Pid = pid, Code = code, - ElapsedTime = elapsedTime + ElapsedTime = elapsedTime, + Depth = ProcessManager.Depth }); } @@ -426,8 +435,11 @@ private void WriteMessage(Trace2Message message) public abstract class Trace2Message { - protected const string TimeFormat = "yyyy'-'MM'-'dd'T'HH':'mm':'ss'.'ffffff'Z'"; private const int SourceColumnMaxWidth = 23; + private const string NormalPerfTimeFormat = "HH:mm:ss.ffffff"; + + protected const string EmptyPerformanceSpan = "| | | | "; + protected const string TimeFormat = "yyyy'-'MM'-'dd'T'HH':'mm':'ss'.'ffffff'Z'"; [JsonProperty("event", Order = 1)] public Trace2Event Event { get; set; } @@ -449,34 +461,122 @@ public abstract class Trace2Message [JsonProperty("line", Order = 6)] public int Line { get; set; } + [JsonProperty("depth", Order = 7)] + public int Depth { get; set; } + public abstract string ToJson(); public abstract string ToNormalString(); - protected string BuildNormalString(string message) + public abstract string ToPerformanceString(); + + protected abstract string BuildPerformanceSpan(); + + protected string BuildNormalString() { + string message = GetEventMessage(Trace2FormatTarget.Normal); + // The normal format uses local time rather than UTC time. - string time = Time.ToLocalTime().ToString("HH:mm:ss.ffffff"); + string time = Time.ToLocalTime().ToString(NormalPerfTimeFormat); + string source = GetSource(); + + // Git's TRACE2 normal format is: + // [