diff --git a/src/AzurePipelines/PipelineCachingCacheClient.cs b/src/AzurePipelines/PipelineCachingCacheClient.cs index ba0f17e..44d1bd6 100644 --- a/src/AzurePipelines/PipelineCachingCacheClient.cs +++ b/src/AzurePipelines/PipelineCachingCacheClient.cs @@ -8,6 +8,7 @@ using System.Linq; using System.Runtime.CompilerServices; using System.Text; +using System.Text.RegularExpressions; using System.Threading; using System.Threading.Tasks; using BuildXL.Cache.ContentStore.Hashing; @@ -110,23 +111,24 @@ public PipelineCachingCacheClient( _universe = $"pccc-{(int)hasher.Info.HashType}-{InternalSeed}-" + (string.IsNullOrEmpty(universe) ? "DEFAULT" : universe); _azureDevopsTracer = new CallbackAppTraceSource( - (message, level) => + (rawMessage, level) => { + TryExtractContext(rawMessage, out Context cacheContext, out string message); message = $"PipelineCachingCacheClient [{level}]: {message}"; switch (level) { case SourceLevels.Critical: case SourceLevels.Error: - Tracer.Error(rootContext, message); + Tracer.Error(cacheContext, message); break; case SourceLevels.Warning: - Tracer.Warning(rootContext, message); + Tracer.Warning(cacheContext, message); break; case SourceLevels.Information: - Tracer.Info(rootContext, message); + Tracer.Info(cacheContext, message); break; case SourceLevels.Verbose: - Tracer.Debug(rootContext, message); + Tracer.Debug(cacheContext, message); break; default: throw new InvalidOperationException($"Unexpected SourceLevel:{level}"); @@ -265,7 +267,8 @@ protected override async Task AddNodeAsync( var result = await WithHttpRetries( () => _manifestClient.PublishAsync(RepoRoot, infos, extras, new ArtifactPublishOptions(), manifestFileOutputPath: null, cancellationToken), - context: $"Publishing content for {fingerprint}", + cacheContext: context, + message: $"Publishing content for {fingerprint}", cancellationToken); // double check @@ -287,7 +290,8 @@ protected override async Task AddNodeAsync( CreateResult createResult = await WithHttpRetries( () => _cacheClient.CreatePipelineCacheArtifactAsync(entry, null, cancellationToken), - context.ToString()!, + cacheContext: context, + message: $"Storing cache key for {fingerprint}", cancellationToken); Tracer.Debug(context, $"Cache entry stored in scope `{createResult.ScopeUsed}`"); } @@ -357,7 +361,8 @@ protected override async Task AddNodeAsync( var result = await WithHttpRetries( () => _manifestClient.PublishAsync(TempFolder, infos, extras, new ArtifactPublishOptions(), manifestFileOutputPath: null, cancellationToken), - context.ToString()!, + cacheContext: context, + message: $"Publishing content for {fingerprint}", cancellationToken); var entry = new CreatePipelineCacheArtifactContract( @@ -369,7 +374,8 @@ protected override async Task AddNodeAsync( CreateResult createResult = await WithHttpRetries( () => _cacheClient.CreatePipelineCacheArtifactAsync(entry, null, cancellationToken), - context.ToString()!, + cacheContext: context, + message: $"Storing cache key for {fingerprint}", cancellationToken); Tracer.Debug(context, $"SFP `{fingerprint}` stored in scope `{createResult.ScopeUsed}`"); @@ -559,7 +565,8 @@ await _client.WithHttpRetries( await _client._manifestClient.DownloadAsyncWithManifestPath(manifestOptions, cancellationToken); return 0; }, - context: context.ToString()!, + cacheContext: context, + message: $"Downloading for {_manifestId}", cancellationToken); foreach (KeyValuePair addToCache in toAddToCacheAsWholeFile) @@ -607,12 +614,13 @@ private async Task GetBytes(Context context, DedupIdentifier dedupId, Ca { using var ms = new MemoryStream(); return await WithHttpRetries(async () => - { - ms.Position = 0; - await _manifestClient.DownloadToStreamAsync(dedupId, ms, proxyUri: null, cancellationToken); - return ms.ToArray(); - }, - context.ToString()!, + { + ms.Position = 0; + await _manifestClient.DownloadToStreamAsync(dedupId, ms, proxyUri: null, cancellationToken); + return ms.ToArray(); + }, + cacheContext: context, + message: $"Getting bytes of {dedupId}", cancellationToken); } @@ -712,11 +720,12 @@ private string ComputeSelectorsKey(BuildXL.Cache.MemoizationStore.Interfaces.Ses return null; } }, - $"Querying cache for '{key}'", + cacheContext: context, + message: $"Querying cache for '{key}'", cancellationToken); } - private Task WithHttpRetries(Func> taskFactory, string context, CancellationToken token) + private Task WithHttpRetries(Func> taskFactory, Context cacheContext, string message, CancellationToken token) { return AsyncHttpRetryHelper.InvokeAsync( taskFactory, @@ -725,7 +734,7 @@ private Task WithHttpRetries(Func> taskFactory, string context, Ca canRetryDelegate: _ => true, // retry on any exception cancellationToken: token, continueOnCapturedContext: false, - context: context); + context: EmbedCacheContext(cacheContext, message)); } public override async ValueTask DisposeAsync() @@ -768,4 +777,27 @@ private string ConvertAbsolutePathToUriPath(string path) // Prepend a '/' return $"/{path}"; } + + private const string EmbeddedCacheContextHeader = "[[CacheContext:"; + private static readonly Regex extractCacheContext = new Regex(@"\[\[CacheContext:(.*)\]\](.*)", RegexOptions.Compiled); + + private static string EmbedCacheContext(Context cacheContext, string message) => + $"{EmbeddedCacheContextHeader}{cacheContext.TraceId}]]{message}"; + + private void TryExtractContext(string both, out Context context, out string message) + { + Match match; + if (both.StartsWith(EmbeddedCacheContextHeader, StringComparison.Ordinal) && + (match = extractCacheContext.Match(both)).Success && + Guid.TryParse(match.Captures[0].Value, out Guid contextGuid)) + { + context = new Context(contextGuid, RootContext.Logger); + message = match.Captures[1].Value; + } + else + { + message = both; + context = RootContext; + } + } } diff --git a/src/Common/MSBuildCachePluginBase.cs b/src/Common/MSBuildCachePluginBase.cs index 17adb49..ea6d1d6 100644 --- a/src/Common/MSBuildCachePluginBase.cs +++ b/src/Common/MSBuildCachePluginBase.cs @@ -11,6 +11,7 @@ using System.IO; using System.Linq; using System.Reflection; +using System.Runtime.CompilerServices; using System.Text; using System.Text.Json; using System.Threading; @@ -209,18 +210,8 @@ protected virtual IFingerprintFactory CreateFingerprintFactory() protected FileRealizationMode GetFileRealizationMode(string path) => IsDuplicateIdenticalOutputPath(_pluginLogger!, path) ? FileRealizationMode.CopyNoVerify : FileRealizationMode.Any; - public async override Task BeginBuildAsync(CacheContext context, PluginLoggerBase logger, CancellationToken cancellationToken) - { - try - { - await BeginBuildInnerAsync(context, logger, cancellationToken); - } - catch (Exception e) - { - logger.LogWarning($"{nameof(BeginBuildAsync)}: {e}"); - throw; - } - } + public override Task BeginBuildAsync(CacheContext context, PluginLoggerBase logger, CancellationToken cancellationToken) + => TimeAndLogAsync(logger, () => BeginBuildInnerAsync(context, logger, cancellationToken)); private async Task BeginBuildInnerAsync(CacheContext context, PluginLoggerBase logger, CancellationToken cancellationToken) { @@ -318,18 +309,8 @@ private async Task BeginBuildInnerAsync(CacheContext context, PluginLoggerBase l Initialized = true; } - public override async Task EndBuildAsync(PluginLoggerBase logger, CancellationToken cancellationToken) - { - try - { - await EndBuildInnerAsync(logger, cancellationToken); - } - catch (Exception e) - { - logger.LogWarning($"{nameof(EndBuildAsync)}: {e}"); - throw; - } - } + public override Task EndBuildAsync(PluginLoggerBase logger, CancellationToken cancellationToken) + => TimeAndLogAsync(logger, () => EndBuildInnerAsync(logger, cancellationToken)); private async Task EndBuildInnerAsync(PluginLoggerBase logger, CancellationToken cancellationToken) { @@ -345,18 +326,11 @@ private async Task EndBuildInnerAsync(PluginLoggerBase logger, CancellationToken _pluginLogger = null; } - public override async Task GetCacheResultAsync(BuildRequestData buildRequest, PluginLoggerBase logger, CancellationToken cancellationToken) - { - try - { - return await GetCacheResultInnerAsync(buildRequest, logger, cancellationToken); - } - catch (Exception e) - { - logger.LogWarning($"{nameof(GetCacheResultAsync)}: {e}"); - throw; - } - } + public override Task GetCacheResultAsync(BuildRequestData buildRequest, PluginLoggerBase logger, CancellationToken cancellationToken) + => TimeAndLogAsync( + logger, + () => GetCacheResultInnerAsync(buildRequest, logger, cancellationToken), + context: buildRequest.ProjectFullPath); private async Task GetCacheResultInnerAsync(BuildRequestData buildRequest, PluginLoggerBase logger, CancellationToken cancellationToken) { @@ -403,22 +377,12 @@ private async Task GetCacheResultInnerAsync(BuildRequestData buildR } public override void HandleFileAccess(FileAccessContext fileAccessContext, FileAccessData fileAccessData) - { - _hasHadFileAccessReport = true; - - try - { - HandleFileAccessInner(fileAccessContext, fileAccessData); - } - catch (Exception e) - { - _pluginLogger?.LogWarning($"{nameof(HandleFileAccess)}: {e}"); - throw; - } - } + => TimeAndLog(_pluginLogger, () => HandleFileAccessInner(fileAccessContext, fileAccessData)); private void HandleFileAccessInner(FileAccessContext fileAccessContext, FileAccessData fileAccessData) { + _hasHadFileAccessReport = true; + if (!Initialized) { return; @@ -434,17 +398,7 @@ private void HandleFileAccessInner(FileAccessContext fileAccessContext, FileAcce } public override void HandleProcess(FileAccessContext fileAccessContext, ProcessData processData) - { - try - { - HandleProcessInner(fileAccessContext, processData); - } - catch (Exception e) - { - _pluginLogger?.LogWarning($"{nameof(HandleProcessInner)}: {e}"); - throw; - } - } + => TimeAndLog(_pluginLogger, () => HandleProcessInner(fileAccessContext, processData)); private void HandleProcessInner(FileAccessContext fileAccessContext, ProcessData processData) { @@ -462,18 +416,11 @@ private void HandleProcessInner(FileAccessContext fileAccessContext, ProcessData _fileAccessRepository.AddProcess(nodeContext, processData); } - public override async Task HandleProjectFinishedAsync(FileAccessContext fileAccessContext, BuildResult buildResult, PluginLoggerBase logger, CancellationToken cancellationToken) - { - try - { - await HandleProjectFinishedInnerAsync(fileAccessContext, buildResult, logger, cancellationToken); - } - catch (Exception e) - { - logger.LogWarning($"{nameof(HandleProjectFinishedAsync)}: {e}"); - throw; - } - } + public override Task HandleProjectFinishedAsync(FileAccessContext fileAccessContext, BuildResult buildResult, PluginLoggerBase logger, CancellationToken cancellationToken) + => TimeAndLogAsync( + logger, + () => HandleProjectFinishedInnerAsync(fileAccessContext, buildResult, logger, cancellationToken), + context: fileAccessContext.ProjectFullPath); private async Task HandleProjectFinishedInnerAsync(FileAccessContext fileAccessContext, BuildResult buildResult, PluginLoggerBase logger, CancellationToken cancellationToken) { @@ -1145,6 +1092,48 @@ private void CheckForDuplicateOutputs(PluginLoggerBase logger, IReadOnlyDictiona logger.LogMessage($"Node {nodeContext.Id} produced duplicate-identical output {relativeFilePath} which was already produced by another node {previousNode.Id}. Allowing as content is the same."); } } + + private static async Task TimeAndLogAsync(PluginLoggerBase? logger, Func> innerAsync, string? context = null, [CallerMemberName] string memberName = "") + { + var timer = Stopwatch.StartNew(); + try + { + return await innerAsync(); + } + catch (Exception e) + { + if (context == null) + { + logger?.LogWarning($"{memberName} failed after {timer.ElapsedMilliseconds} ms: {e}"); + } + else + { + logger?.LogWarning($"{memberName}({context}) failed after {timer.ElapsedMilliseconds} ms: {e}"); + } + throw; + } + finally + { + // only log 1+ second operations to avoid debug spew + if (timer.ElapsedMilliseconds > 1000.0) + { + if (context == null) + { + logger?.LogMessage($"{memberName} succeeded after {timer.ElapsedMilliseconds} ms."); + } + else + { + logger?.LogMessage($"{memberName}({context}) succeeded after {timer.ElapsedMilliseconds} ms."); + } + } + } + } + + private static Task TimeAndLogAsync(PluginLoggerBase? logger, Func innerAsync, string? context = null, [CallerMemberName] string memberName = "") + => TimeAndLogAsync(logger, async () => { await innerAsync(); return 0; }, context, memberName); + + private static void TimeAndLog(PluginLoggerBase? logger, Action inner, string? context = null, [CallerMemberName] string memberName = "") + => TimeAndLogAsync(logger, () => { inner(); return Task.CompletedTask; }, context, memberName).GetAwaiter().GetResult(); } public static class ProjectGraphNodeExtensions