Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Add context to Pipeline Caching log traces #70

Merged
merged 4 commits into from
May 28, 2024
Merged

Add context to Pipeline Caching log traces #70

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
4 commits
Select commit Hold shift + click to select a range
5c65900
add context to PC
johnterickson Apr 26, 2024
a69031e
measure plugin callback times
johnterickson Apr 29, 2024
c32f157
log less
johnterickson Apr 29, 2024
27aa1f6
more logging
johnterickson May 24, 2024
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
70 changes: 51 additions & 19 deletions src/AzurePipelines/PipelineCachingCacheClient.cs
View file
Open in desktop
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)
dfederm marked this conversation as resolved.
Show resolved Hide resolved
{
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
Open in desktop
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