Skip to content

Split blob-hydration and directory-enumeration failure telemetry by cause #2071

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

Draft
tyrielv wants to merge 1 commit into
base: master
Choose a base branch
from
Draft

Split blob-hydration and directory-enumeration failure telemetry by cause #2071

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
1 commit
Select commit
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
69 changes: 67 additions & 2 deletions GVFS/GVFS.Common/Git/GVFSGitObjects.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -33,14 +33,48 @@ public enum RequestSource
SymLinkCreation,
}

/// <summary>
/// Why a blob-hydration request ultimately failed. Recorded on the terminal failure
/// telemetry so failures outside gvfs.exe's control (network, local disk/IO, ProjFS)
/// can be told apart from failures that point at an actionable bug or a server/data
/// problem. Kept in sync with the telemetry bucketing in the devprod.git.telemetry
/// workbook (gvfs-regression-signatures.kql).
/// </summary>
public enum BlobHydrationFailureCategory
{
None = 0,

// Outside gvfs.exe's control:
NetworkUnavailable, // A network/HTTP-layer exception while fetching the blob.
DownloadFailed, // The blob download reported failure (transient/unclassified).
LocalIO, // IOException reading the local object or streaming to the ProjFS buffer.
ProjFSWriteFailed, // ProjFS WriteFileData returned a non-recoverable error.

// Actionable (bug, corruption, or server/data problem):
ObjectNotOnServer, // The cache server returned 404 for the blob.
LocalCopyFailed, // Blob downloaded, but the subsequent local copy still failed.
SizeMismatch, // Blob length did not match the length ProjFS requested.
Unexpected, // Unclassified exception.
}

protected GVFSContext Context { get; private set; }

public virtual bool TryCopyBlobContentStream(
string sha,
CancellationToken cancellationToken,
RequestSource requestSource,
Action<Stream, long> writeAction)
Action<Stream, long> writeAction,
out BlobHydrationFailureCategory failureCategory)
{
// Track the outcome of the most recent attempt so that the terminal failure
// telemetry can attribute the failure to a cause (network vs. object-missing vs.
// local copy) that is otherwise collapsed into the bool return value below. The
// final category is also surfaced via the out parameter so the caller can tag its
// own terminal telemetry with the same cause.
DownloadAndSaveObjectResult lastDownloadResult = DownloadAndSaveObjectResult.Error;
bool downloadSucceededButCopyFailed = false;
BlobHydrationFailureCategory capturedCategory = BlobHydrationFailureCategory.None;

RetryWrapper<bool> retrier = new RetryWrapper<bool>(this.GitObjectRequestor.RetryConfig.MaxAttempts, cancellationToken);
retrier.OnFailure +=
errorArgs =>
Expand All @@ -50,10 +84,35 @@ public virtual bool TryCopyBlobContentStream(
metadata.Add("AttemptNumber", errorArgs.TryCount);
metadata.Add("WillRetry", errorArgs.WillRetry);

BlobHydrationFailureCategory category;
if (errorArgs.Error != null)
{
metadata.Add("Exception", errorArgs.Error.ToString());

// An IOException here can also originate in the download/network layer, but
// we cannot tell where it came from, so it is bucketed as local IO.
category = errorArgs.Error is IOException
? BlobHydrationFailureCategory.LocalIO
: BlobHydrationFailureCategory.NetworkUnavailable;
}
else if (downloadSucceededButCopyFailed)
{
category = BlobHydrationFailureCategory.LocalCopyFailed;
}
else if (lastDownloadResult == DownloadAndSaveObjectResult.ObjectNotOnServer)
{
category = BlobHydrationFailureCategory.ObjectNotOnServer;
}
else
{
// The download reported failure without an exception; the cause (network,
// disk-save, etc.) is unclassified, so use the neutral DownloadFailed bucket
// rather than over-asserting NetworkUnavailable.
category = BlobHydrationFailureCategory.DownloadFailed;
}

capturedCategory = category;
metadata.Add(nameof(BlobHydrationFailureCategory), category.ToString());

string message = "TryCopyBlobContentStream: Failed to provide blob contents";
if (errorArgs.WillRetry)
Expand All @@ -76,19 +135,25 @@ public virtual bool TryCopyBlobContentStream(
}
else
{
downloadSucceededButCopyFailed = false;

// Pass in false for retryOnFailure because the retrier in this method manages multiple attempts
if (this.TryDownloadAndSaveObject(sha, cancellationToken, requestSource, retryOnFailure: false) == DownloadAndSaveObjectResult.Success)
lastDownloadResult = this.TryDownloadAndSaveObject(sha, cancellationToken, requestSource, retryOnFailure: false);
if (lastDownloadResult == DownloadAndSaveObjectResult.Success)
{
if (this.Context.Repository.TryCopyBlobContentStream(sha, writeAction))
{
return new RetryWrapper<bool>.CallbackResult(true);
}

downloadSucceededButCopyFailed = true;
}

return new RetryWrapper<bool>.CallbackResult(error: null, shouldRetry: true);
}
});

failureCategory = invokeResult.Result ? BlobHydrationFailureCategory.None : capturedCategory;
return invokeResult.Result;
}

Expand Down
76 changes: 71 additions & 5 deletions GVFS/GVFS.Platform.Windows/WindowsFileSystemVirtualizer.cs
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -59,6 +59,24 @@ public class WindowsFileSystemVirtualizer : FileSystemVirtualizer, IRequiredCall
// the throttle cannot be disturbed by wall-clock adjustments.
private long lastEnumerationEvictionSweepTickCount = Environment.TickCount64;

// Enumeration IDs recently removed by EvictStaleEnumerations, mapped to the monotonic tick at
// which they were evicted. Retained briefly so a later GetDirectoryEnumeration for an evicted
// ID can be attributed to GVFS eviction (self-inflicted) rather than a ProjFS unknown-ID
// delivery. Bounded by pruning during each sweep; empty while eviction is disabled (the default).
private readonly ConcurrentDictionary<Guid, long> recentlyEvictedEnumerations = new ConcurrentDictionary<Guid, long>();

/// <summary>
/// Why a GetDirectoryEnumeration failed to find its enumeration ID. Recorded on the failure
/// telemetry so a self-inflicted eviction can be told apart from a ProjFS unknown-ID delivery.
/// Kept in sync with the telemetry bucketing in devprod.git.telemetry
/// (gvfs-regression-signatures.kql).
/// </summary>
public enum EnumerationFailureReason
{
Unknown = 0, // ProjFS delivered an ID GVFS never held or already ended (outside gvfs.exe's control).
Evicted, // GVFS's own stale-enumeration eviction removed a live enumeration (self-inflicted).
}

public WindowsFileSystemVirtualizer(GVFSContext context, GVFSGitObjects gitObjects)
: this(
context,
Expand Down Expand Up @@ -187,19 +205,51 @@ private void MaybeEvictStaleEnumerations()

private void EvictStaleEnumerations()
{
long now = Environment.TickCount64;

// Prune the eviction-tracking map on every sweep, independent of whether an eviction
// happens this pass, so entries never outlive the window in which a stale
// GetDirectoryEnumeration could still arrive for an evicted ID. (If this ran only when
// Count > max below, the last evicted batch would linger once activity subsided.) Guids
// are never reused, so there is no need to prune on re-add. Cheap no-op while empty
// (the default, since eviction is off).
if (!this.recentlyEvictedEnumerations.IsEmpty)
{
long trackingCutoff = now - (long)(2 * this.activeEnumerationStaleTimeout.TotalMilliseconds);
foreach (KeyValuePair<Guid, long> tracked in this.recentlyEvictedEnumerations)
{
if (tracked.Value < trackingCutoff)
{
this.recentlyEvictedEnumerations.TryRemove(tracked.Key, out _);
}
}
}

if (this.activeEnumerations.Count <= this.maxActiveEnumerations)
{
return;
}

long cutoff = Environment.TickCount64 - (long)this.activeEnumerationStaleTimeout.TotalMilliseconds;
long cutoff = now - (long)this.activeEnumerationStaleTimeout.TotalMilliseconds;
int evictedCount = 0;
foreach (KeyValuePair<Guid, ActiveEnumeration> entry in this.activeEnumerations)
{
if (entry.Value.LastActivityTickCount < cutoff &&
this.activeEnumerations.TryRemove(entry.Key, out _))
if (entry.Value.LastActivityTickCount < cutoff)
{
evictedCount++;
// Record the eviction BEFORE removing from activeEnumerations so a concurrent
// GetDirectoryEnumeration for this ID always finds it in one map or the other,
// and is never mis-attributed to a ProjFS unknown-ID delivery.
this.recentlyEvictedEnumerations[entry.Key] = now;
if (this.activeEnumerations.TryRemove(entry.Key, out _))
{
evictedCount++;
}
else
{
// Lost the race (e.g. a normal EndDirectoryEnumeration removed it first);
// it was not evicted by us, so undo the tracking entry.
this.recentlyEvictedEnumerations.TryRemove(entry.Key, out _);
}
}
}

Expand Down Expand Up @@ -464,6 +514,16 @@ public HResult GetDirectoryEnumerationCallback(
EventMetadata metadata = this.CreateEventMetadata(enumerationId);
metadata.Add("filterFileName", filterFileName);
metadata.Add("restartScan", restartScan);

// Distinguish a failure caused by GVFS's own stale-enumeration eviction
// (self-inflicted, fixable) from ProjFS delivering an ID GVFS never held or
// already ended (outside gvfs.exe's control). Kept in sync with the telemetry
// bucketing in devprod.git.telemetry (gvfs-regression-signatures.kql).
EnumerationFailureReason enumerationFailureReason = this.recentlyEvictedEnumerations.ContainsKey(enumerationId)
? EnumerationFailureReason.Evicted
: EnumerationFailureReason.Unknown;
metadata.Add(nameof(EnumerationFailureReason), enumerationFailureReason.ToString());

this.Context.Tracer.RelatedError(metadata, nameof(this.GetDirectoryEnumerationCallback) + ": Failed to find active enumeration ID");

return HResult.InternalError;
Expand Down Expand Up @@ -1180,6 +1240,7 @@ private void GetFileStreamHandlerAsyncHandler(
if (blobLength != length)
{
requestMetadata.Add("blobLength", blobLength);
requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.SizeMismatch.ToString());
this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: Actual file length (blobLength) does not match requested length");

throw new GetFileStreamException(HResult.InternalError);
Expand All @@ -1204,6 +1265,7 @@ private void GetFileStreamHandlerAsyncHandler(
catch (IOException e)
{
requestMetadata.Add("Exception", e.ToString());
requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.LocalIO.ToString());
this.Context.Tracer.RelatedError(requestMetadata, "IOException while copying to unmanaged buffer.");

throw new GetFileStreamException("IOException while copying to unmanaged buffer: " + e.Message, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable);
Expand All @@ -1225,6 +1287,7 @@ private void GetFileStreamHandlerAsyncHandler(

default:
{
requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.ProjFSWriteFailed.ToString());
this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.virtualizationInstance.WriteFileData)} failed, error: " + writeResult.ToString("X") + "(" + writeResult.ToString("G") + ")");
}

Expand All @@ -1235,8 +1298,10 @@ private void GetFileStreamHandlerAsyncHandler(
}
}
}
}))
},
out GVFSGitObjects.BlobHydrationFailureCategory failureCategory))
{
requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), failureCategory.ToString());
this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: TryCopyBlobContentStream failed");

this.TryCompleteCommand(commandId, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable);
Expand Down Expand Up @@ -1264,6 +1329,7 @@ private void GetFileStreamHandlerAsyncHandler(
catch (Exception e)
{
requestMetadata.Add("Exception", e.ToString());
requestMetadata.Add(nameof(GVFSGitObjects.BlobHydrationFailureCategory), GVFSGitObjects.BlobHydrationFailureCategory.Unexpected.ToString());
this.Context.Tracer.RelatedError(requestMetadata, $"{nameof(this.GetFileStreamHandlerAsyncHandler)}: TryCopyBlobContentStream failed");

this.TryCompleteCommand(commandId, (HResult)HResultExtensions.HResultFromNtStatus.FileNotAvailable);
Expand Down
Loading
Loading