Merged PR 812625: Improve user friendliness of pip timeout arguments

Allows the arguments to be specified with a time unit, and also logs it with an assumed friendlier unit instead of milliseconds
This commit is contained in:
Marcelo Lynch 2024-11-01 18:36:13 +00:00
Родитель 66beb05120
Коммит 9561b49669
7 изменённых файлов: 143 добавлений и 17 удалений

Просмотреть файл

@ -152,8 +152,8 @@ This page lists flags that can be used to configure BuildXL.
| PathSetThreshold | The maximum number of visited path sets allowed before switching to an 'augmented' weak fingerprint computed from common dynamically accessed paths. |
| Phase | Specifies the phase until which {ShortProductName} runs. Allowed values are None (no phase is run), Parse (run until parsing is done), Schedule (run until scheduling is done), Execute (run until execution is done). Default is Execute. |
| PinCachedOutputs | Indicates whether outputs should be pinned in CAS for cached pips. Defaults to on. |
| PipDefaultTimeout | How long to wait before terminating individual processes, in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process. |
| PipDefaultWarningTimeout | After how much time to issue a warning that an individual process runs too long, in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process. |
| PipDefaultTimeout | How long to wait before terminating individual processes. The argument allows an expression that represents a time duration, like "3s", "500ms", "30m", "1.5h". The allowed suffixes are 'ms', 's', 'm', 'h', and no suffix is interpreted as an amount in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process. |
| PipDefaultWarningTimeout | After how much time to issue a warning that an individual process runs too long. The argument allows an expression that represents a time duration, like "3s", "500ms", "30m", "1.5h". The allowed suffixes are 'ms', 's', 'm', 'h', and no suffix is interpreted as an amount in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process. |
| PipProperty | Sets execution behaviors for a pip. Supported properties: <br> PipFingerprintSalt - adds a pip specific salt value or '*' for a random salt. Ex: /pipProperty:Pip4354554[PipFingerprintingSalt=*] <br> EnableVerboseProcessLogging - Enables verbose sandbox logging for specific pips. This is equivalent to switching /logObservedFileAccesses and /logProcesses for these pips, and also enabling verbose debug logging in the sandbox. Example: /pipProperty:Pip232325435435[EnableVerboseProcessLogging] |
| PipTimeoutMultiplier | Multiplier applied to the final timeout for individual processes. Setting a multiplier greater than one will increase the timeout accordingly for all pips, even those with an explicit non-default timeout set. |
| PipWarningTimeoutMultiplier | Multiplier applied to the warning timeout for individual processes. Setting a multiplier greater than one will increase the warning timeout accordingly for all pips, even those with an explicit non-default warning timeout set. |

Просмотреть файл

@ -827,12 +827,12 @@ namespace BuildXL
"pipDefaultTimeout",
opt =>
sandboxConfiguration.DefaultTimeout =
CommandLineUtilities.ParseInt32Option(opt, 1, (int)Process.MaxTimeout.TotalMilliseconds)),
CommandLineUtilities.ParseDurationOptionToMilliseconds(opt, 1, (int)Process.MaxTimeout.TotalMilliseconds)),
OptionHandlerFactory.CreateOption(
"pipDefaultWarningTimeout",
opt =>
sandboxConfiguration.DefaultWarningTimeout =
CommandLineUtilities.ParseInt32Option(opt, 1, (int)Process.MaxTimeout.TotalMilliseconds)),
CommandLineUtilities.ParseDurationOptionToMilliseconds(opt, 1, (int)Process.MaxTimeout.TotalMilliseconds)),
OptionHandlerFactory.CreateOption(
"pipTimeoutMultiplier",
opt => sandboxConfiguration.TimeoutMultiplier = (int)CommandLineUtilities.ParseDoubleOption(opt, 0.000001, 1000000)),

Просмотреть файл

@ -1127,10 +1127,10 @@ Example: ad2d42d2ec5d2ca0c0b7ad65402d07c7ef40b91e</value>
<value>When enabled, {ShortProductName} will not intercept ZwCreateFile, ZwOpenFile, and ZwQueryDirectoryFile calls. This might lead to incorrect builds because some file accesses will not be enforced. This flag is off by default.</value>
</data>
<data name="HelpText_DisplayHelp_PipDefaultTimeout" xml:space="preserve">
<value>How long to wait before terminating individual processes, in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process.</value>
<value>How long to wait before terminating individual processes. The argument allows an expression that represents a time duration, like "3s", "500ms", "30m", "1.5h". The allowed suffixes are 'ms', 's', 'm', 'h', and no suffix is interpreted as an amount in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process.</value>
</data>
<data name="HelpText_DisplayHelp_PipDefaultWarningTimeout" xml:space="preserve">
<value>After how much time to issue a warning that an individual process runs too long, in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process.</value>
<value>After how much time to issue a warning that an individual process runs too long. The argument allows an expression that represents a time duration, like "3s", "500ms", "30m", "1.5h". The allowed suffixes are 'ms', 's', 'm', 'h', and no suffix is interpreted as an amount in milliseconds. Setting this value will only have an effect if no other timeout is specified for a process.</value>
</data>
<data name="HelpText_DisplayHelp_Debug_LoadGraph" xml:space="preserve">
<value>Loads a cached build graph stored under the given fingerprint (40 digit hex string, no delimiters), path to cached graph directory, or canonical name.</value>

Просмотреть файл

@ -4668,14 +4668,30 @@ namespace BuildXL.ProcessPipExecutor
private void LogFinishedFailed(SandboxedProcessResult result) =>
Logger.Log.PipProcessFinishedFailed(m_loggingContext, m_pip.SemiStableHash, m_pipDescription, result.ExitCode);
private string DurationForLog(TimeSpan duration)
{
if (duration.TotalSeconds < 1)
{
return $"{(int)duration.TotalMilliseconds}ms";
}
else if (duration.TotalMinutes < 1)
{
return $"{(int)duration.TotalSeconds}s";
}
else
{
return $"{Bound(duration.TotalMinutes)}min";
}
}
private void LogTookTooLongWarning(TimeSpan timeout, TimeSpan time, TimeSpan warningTimeout) =>
Logger.Log.PipProcessTookTooLongWarning(
m_loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
Bound(time.TotalMilliseconds),
Bound(warningTimeout.TotalMilliseconds),
Bound(timeout.TotalMilliseconds));
DurationForLog(time),
DurationForLog(warningTimeout),
DurationForLog(timeout));
private void LogTookTooLongError(SandboxedProcessResult result, TimeSpan timeout, TimeSpan time,
string stdError, string stdOut, bool errorWasTruncated, bool errorWasFiltered)
@ -4698,8 +4714,8 @@ namespace BuildXL.ProcessPipExecutor
m_loggingContext,
m_pip.SemiStableHash,
m_pipDescription,
Bound(time.TotalMilliseconds),
Bound(timeout.TotalMilliseconds),
DurationForLog(time),
DurationForLog(timeout),
dumpString,
EnsureToolOutputIsNotEmpty(outputTolog));
}

Просмотреть файл

@ -189,14 +189,14 @@ namespace BuildXL.Processes.Tracing
Keywords = (int)Keywords.UserMessage,
EventTask = (int)Tasks.PipExecutor,
Message =
EventConstants.PipPrefix + "Process ran for {2}ms, which is longer than the warning timeout of {3}ms; the process will be terminated if it ever runs longer than {4}ms")]
EventConstants.PipPrefix + "Process ran for {2}, which is longer than the warning timeout of {3}; the process will be terminated if it ever runs longer than {4}")]
public abstract void PipProcessTookTooLongWarning(
LoggingContext context,
long pipSemiStableHash,
string pipDescription,
long actual,
long softMax,
long hardMax);
string actual,
string softMax,
string hardMax);
[GeneratedEvent(
(int)LogEventId.PipProcessTookTooLongError,
@ -204,8 +204,8 @@ namespace BuildXL.Processes.Tracing
EventLevel = Level.Error,
Keywords = (int)(Keywords.UserMessage | Keywords.UserError),
EventTask = (int)Tasks.PipExecutor,
Message = EventConstants.PipPrefix + "Process terminated because it took too long: {2}ms; the timeout is set to {3}ms. {4} \r\n Process Output: \r\n {5}")]
public abstract void PipProcessTookTooLongError(LoggingContext context, long pipSemiStableHash, string pipDescription, long actual, long time, string dumpDetails, string outputToLog);
Message = EventConstants.PipPrefix + "Process terminated because it took too long: {2}; the timeout is set to {3}. {4} \r\n Process Output: \r\n {5}")]
public abstract void PipProcessTookTooLongError(LoggingContext context, long pipSemiStableHash, string pipDescription, string actual, string time, string dumpDetails, string outputToLog);
[GeneratedEvent(
(int)LogEventId.PipProcessStandardOutput,

Просмотреть файл

@ -68,6 +68,19 @@ namespace BuildXL.ToolSupport
/// </summary>
private static readonly char[] s_separators = { ':' };
/// <summary>
/// Used to parse time duration options
/// </summary>
private static readonly (string, int)[] s_durationFactorBySuffix =
[
("ms", 1), // Order matters so we try ms before s
("s", 1000),
("m", 1000 * 60),
("min", 1000 * 60),
("h", 1000 * 60 * 60)
];
/// <summary>
/// Wraps a command-line for easy consumption.
/// </summary>
@ -622,6 +635,63 @@ namespace BuildXL.ToolSupport
return result;
}
/// <summary>
/// Parse an option that represents a time duration: the allowed suffixes are 'ms', 's', 'm', 'h'
/// If no suffix is specified the amount is interpreted in milliseconds
/// </summary>
public static int ParseDurationOptionToMilliseconds(Option opt, int minValue, int maxValue)
{
if (string.IsNullOrEmpty(opt.Value))
{
throw Error("The /{0} argument requires a value.", opt.Name);
}
var input = opt.Value;
if (double.TryParse(input, out double doubleValue))
{
return ranged(doubleValue);
}
// We'll do a very naive parsing, but good enough, this is called at most a couple of times
foreach (var (suffix, multiplier) in s_durationFactorBySuffix)
{
if (input.EndsWith(suffix))
{
var numberPart = input.Substring(0, input.Length - suffix.Length);
if (!double.TryParse(numberPart, out doubleValue))
{
// An incorrect suffix was provided
break;
}
var valueInMs = doubleValue * multiplier;
return ranged(valueInMs);
}
}
throw Error(
"The value provided for the /{0} argument is invalid, expecting a numeric expression representing a time period (ending with 'ms', 's', 'm', 'h')",
opt.Name);
int ranged(double x)
{
if (x < minValue || x > maxValue)
{
throw Error(
"The value provided for the /{0} argument is invalid, expecting a duration falling in the range {1}ms..{2}ms but got '{3} = {4}ms'.",
opt.Name,
minValue,
maxValue,
opt.Value,
x);
}
return (int)x;
}
}
/// <summary>
/// Parse an option that produces a uint value.
/// </summary>

Просмотреть файл

@ -521,5 +521,45 @@ Arg1");
var clu = new CommandLineUtilities(args);
XAssert.AreEqual(expectedEndOfCallerArgument, clu.HasEndOfCallerArgument);
}
[Theory]
[InlineData("100", 100)]
[InlineData("20000ms", 20_000)]
[InlineData("100s", 100_000)]
[InlineData("1.5s", 1500)]
[InlineData("1m", 60_000)]
[InlineData("60m", 3_600_000)]
[InlineData("60min", 3_600_000)]
[InlineData("0.5h", 1_800_000)]
[InlineData("1h", 3_600_000)]
[InlineData("999999999999999h", -1)]
[InlineData("233a", -1)]
[InlineData("233mm", -1)]
[InlineData("233msh", -1)]
[InlineData("", -1)]
[InlineData(null, -1)]
public void ParseTimeToMsOption(string value, int expectedValue)
{
const int MinValue = 0;
const int MaxValue = int.MaxValue;
var opt = new CommandLineUtilities.Option
{
Name = "time",
Value = value
};
if (expectedValue == -1)
{
Assert.Throws<InvalidArgumentException>(() =>
{
CommandLineUtilities.ParseDurationOptionToMilliseconds(opt, MinValue, MaxValue);
});
}
else
{
XAssert.AreEqual(expectedValue, CommandLineUtilities.ParseDurationOptionToMilliseconds(opt, MinValue, MaxValue));
}
}
}
}