Skip to content

Commit

Permalink
Add context to Pipeline Caching log traces (#70)
Browse files Browse the repository at this point in the history 
* add context to PC

* measure plugin callback times

* log less

* more logging
  • Loading branch information
@johnterickson
johnterickson authored May 28, 2024
1 parent 16a83fe commit b3dfa78
Show file tree
Hide file tree
Showing 2 changed files with 112 additions and 91 deletions.
70 changes: 51 additions & 19 deletions src/AzurePipelines/PipelineCachingCacheClient.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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}");
Expand Down Expand Up @@ -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
Expand All @@ -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}`");
}
Expand Down Expand Up @@ -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(
Expand All @@ -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}`");
Expand Down Expand Up @@ -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<ContentHash, string> addToCache in toAddToCacheAsWholeFile)
Expand Down Expand Up @@ -607,12 +614,13 @@ private async Task<byte[]> 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);
}

Expand Down Expand Up @@ -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<T> WithHttpRetries<T>(Func<Task<T>> taskFactory, string context, CancellationToken token)
private Task<T> WithHttpRetries<T>(Func<Task<T>> taskFactory, Context cacheContext, string message, CancellationToken token)
{
return AsyncHttpRetryHelper<T>.InvokeAsync(
taskFactory,
Expand All @@ -725,7 +734,7 @@ private Task<T> WithHttpRetries<T>(Func<Task<T>> 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()
Expand Down Expand Up @@ -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;
}
}
}
133 changes: 61 additions & 72 deletions src/Common/MSBuildCachePluginBase.cs
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down Expand Up @@ -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)
{
Expand Down Expand Up @@ -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)
{
Expand All @@ -345,18 +326,11 @@ private async Task EndBuildInnerAsync(PluginLoggerBase logger, CancellationToken
_pluginLogger = null;
}

public override async Task<CacheResult> 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<CacheResult> GetCacheResultAsync(BuildRequestData buildRequest, PluginLoggerBase logger, CancellationToken cancellationToken)
=> TimeAndLogAsync(
logger,
() => GetCacheResultInnerAsync(buildRequest, logger, cancellationToken),
context: buildRequest.ProjectFullPath);

private async Task<CacheResult> GetCacheResultInnerAsync(BuildRequestData buildRequest, PluginLoggerBase logger, CancellationToken cancellationToken)
{
Expand Down Expand Up @@ -403,22 +377,12 @@ private async Task<CacheResult> 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;
Expand All @@ -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)
{
Expand All @@ -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)
{
Expand Down Expand Up @@ -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<T> TimeAndLogAsync<T>(PluginLoggerBase? logger, Func<Task<T>> 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<int> TimeAndLogAsync(PluginLoggerBase? logger, Func<Task> 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
Expand Down

0 comments on commit b3dfa78

Please sign in to comment.