Skip to content

Remove test wall time from xml_test_generator usage #27382

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

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

Remove test wall time from xml_test_generator usage #27382

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
1 change: 0 additions & 1 deletion src/main/java/com/google/devtools/build/lib/exec/StandaloneTestStrategy.java
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -459,7 +459,6 @@ private static Spawn createXmlGeneratingSpawn(
.getCallablePathStringForOs(action.getExecutionSettings().getExecutionOs()),
action.getTestLog().getExecPathString(),
action.getTestXml().getExecPathString(),
Integer.toString(result.getWallTimeInMs() / 1000),
Integer.toString(result.exitCode()));
ImmutableMap.Builder<String, String> envBuilder = ImmutableMap.builder();
// "PATH" and "TEST_BINARY" are also required, they should always be set in testEnv.
Expand Down
9 changes: 1 addition & 8 deletions src/test/py/bazel/test_wrapper_test.py
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -619,18 +619,13 @@ def _AssertXmlGeneration(self, flags):

test_xml = os.path.join(bazel_testlogs, 'foo', 'xml_test', 'test.xml')
self.assertTrue(os.path.exists(test_xml))
duration = 0
xml_contents = []
stdout_lines = []
stderr_lines = []
with open(test_xml, 'rt') as f:
xml_contents = [line.strip() for line in f]
for line in xml_contents:
if 'duration=' in line:
line = line[line.find('duration="') + len('duration="'):]
line = line[:line.find('"')]
duration = int(line)
elif 'stdout_line' in line:
if 'stdout_line' in line:
stdout_lines.append(line)
elif 'stderr_line' in line:
stderr_lines.append(line)
Expand All @@ -642,8 +637,6 @@ def _AssertXmlGeneration(self, flags):
# stdout after L1, then it must be strictly ordered after L1 (but not
# necessarily after L2).
# Therefore we only assert partial ordering of lines.
if duration <= 1:
self._FailWithOutput(xml_contents)
if (len(stdout_lines) != 2 or 'stdout_line_1' not in stdout_lines[0] or
'stdout_line_2' not in stdout_lines[1]):
self._FailWithOutput(xml_contents)
Expand Down
4 changes: 0 additions & 4 deletions src/test/shell/bazel/bazel_test_test.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -735,24 +735,20 @@ EOF
cat bazel-testlogs/dir/success/test.xml >$TEST_log
expect_log "errors=\"0\""
expect_log_once "testcase"
expect_log_once "duration=\"[0-9]\+\""
expect_log "name=\"dir/success\""
cat bazel-testlogs/dir/fail/test.xml >$TEST_log
expect_log "errors=\"1\""
expect_log_once "testcase"
expect_log_once "duration=\"[0-9]\+\""
expect_log "name=\"dir/fail\""

bazel test //dir:all --run_under=exec &> $TEST_log && fail "should have failed" || true
cp bazel-testlogs/dir/success/test.xml $TEST_log
expect_log "errors=\"0\""
expect_log_once "testcase"
expect_log_once "duration=\"[0-9]\+\""
expect_log "name=\"dir/success\""
cp bazel-testlogs/dir/fail/test.xml $TEST_log
expect_log "errors=\"1\""
expect_log_once "testcase"
expect_log_once "duration=\"[0-9]\+\""
expect_log "name=\"dir/fail\""
}

Expand Down
5 changes: 2 additions & 3 deletions tools/test/generate-xml.sh
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -18,8 +18,7 @@ set -euo pipefail

TEST_LOG="$1"
XML_OUTPUT_FILE="$2"
DURATION_IN_SECONDS="$3"
EXIT_CODE="$4"
EXIT_CODE="$3"

function encode_stream {
# Replace invalid XML characters and invalid sequence in CDATA
Expand Down Expand Up @@ -119,7 +118,7 @@ cat >"${XML_OUTPUT_FILE}" <<EOF
<?xml version="1.0" encoding="UTF-8"?>
<testsuites>
<testsuite name="${test_name}" tests="1" failures="0" errors="${errors}">
<testcase name="${test_name}" status="run" duration="${DURATION_IN_SECONDS}" time="${DURATION_IN_SECONDS}">${error_msg}</testcase>
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is very useful for interop with test infrastructure that isn't Bazel-aware. JUnit XML is pretty much universally supported, other means for getting this information would need an adapter.

Generally speaking, wouldn't the test logs, which are also inputs to this action, usually be non-deterministic as well? In that case the XML generation spawn would differ anyway.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The test outputs can be deterministic, or not. The problem here is that regardless of whether they are, if the wall time for the test crosses a second threshold, it automatically changes the command definition from one value to the next, and prevents even deterministically outputting tests from avoiding differences between no-change builds being run to locate determinism issues elsewhere. Objectively, the test isn't in control of whether it gets scheduled enough to avoid modifying its own wall time, no matter how much an author seeks deterministic, reproducible output.
I'm game for marking this up as a test-command option, but figured it may be more useful to avoid this very subjective data altogether than try to cobble conditional xml output.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

While I see how it can be annoying that this introduces non-determinism into an otherwise deterministic test, I've honestly never seen a non-trivial project in which every test emits a deterministic log. In the context of detecting non-determinism, getting rid of the runtime argument would only really make a qualitative difference if that was the case though.

bb explain has special handling for this particular spawn, which is recognized by its TestRunner mnemonic and the basename of the output. What do you think of introducing a distinctive mnemonic (say TestXmlGeneration)? That would make it very easy to filter this out without taking away value from non-Bazel-aware test integrations.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The mnemonic should be switched regardless of the outcome here. Qualifying this activity with the TestRunner is ambiguous and something I've wanted changed for a while, I will submit a separate change.

It's not satisfactory though to say that unlikeliness of universal determinism is a reason to permit this behavior to introduce arbitrary nondeterminism. Cases where overt remote cache misses occur here solely because of this change is the domain of this improvement. Less convincing still is the interest to maintain external tooling. I don't have the option to disable this step of output entirely from bazel's execution, and I don't necessarily know that removing this timing will break any particular downstream parser to ignore the missing content (and its obvious duplication for the use in two fields).
Real timing information is clearly available in bazel-specific contexts, because it exists at higher precision than 1s.

Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

cc @meisterT @tjgq

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

One better than this with further thought. This is a mechanism that, outside of java, no other user of bazel can perform (starlark for instance): modifying the composite state of an action in its command args such that they are only effective and known during the execution phase. I don't care about the presence in the xml, it can be zero for all that matters here, but the unpredictable nature of the action makes the graph mutable, something against the stated intention of bazel. This represents bazel mutating its own "immutable build graph".

Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This is a breaking change to multiple repos I'm aware of. Can we at least put it behind an incompatible flag?

(+1 that in my experience most tests do not have deterministic logging, it's common for logs to contain randomly-generated IDs, timestamps, etc.)

Copy link
Collaborator

@fmeum fmeum Oct 23, 2025 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Cases where overt remote cache misses occur here solely because of this change is the domain of this improvement.

Which situation are you referring to here? If the test execution itself is a cache hit, the subsequent XML generation should be as well since the test runtime is obtained from the cached action result. If a test is forced to rerun somehow then this action could potentially be a cache hit if it didn't contain the time, but that seems to be a pretty rare case.

Note that rules can always avoid running this spawn by generating the XML directly as part of the test action. But that's of course not something users can add without patching or forking rules they don't own.

modifying the composite state of an action in its command args such that they are only effective and known during the execution phase

Starlark can't access action timing data, but aren't tree artifacts and the newly exposed action templates examples of this?

<testcase name="${test_name}" status="run">${error_msg}</testcase>
<system-out>
Generated test.log (if the file is not UTF-8, then this may be unreadable):
<![CDATA[${ENCODED_LOG}]]>
Expand Down
43 changes: 12 additions & 31 deletions tools/test/windows/tw.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -1453,11 +1453,11 @@ bool ParseArgs(int argc, wchar_t** argv, const Path& exec_root,

bool ParseXmlWriterArgs(int argc, wchar_t** argv, const Path& cwd,
Path* out_test_log, Path* out_xml_log,
Duration* out_duration, int* out_exit_code) {
if (argc < 5) {
int* out_exit_code) {
if (argc < 4) {
LogError(__LINE__,
"Usage: $0 <test_output_path> <xml_log_path>"
" <duration_in_seconds> <exit_code>");
" <exit_code>");
return false;
}
if (!out_test_log->Set(argv[1]) || out_test_log->Get().empty()) {
Expand All @@ -1471,13 +1471,8 @@ bool ParseXmlWriterArgs(int argc, wchar_t** argv, const Path& cwd,
return false;
}
out_xml_log->Absolutize(cwd);
if (!out_duration->FromString(argv[3])) {
LogErrorWithArg(__LINE__, "Failed to parse test duration argument",
argv[3]);
return false;
}
if (!ToInt(argv[4], out_exit_code)) {
LogErrorWithArg(__LINE__, "Failed to parse exit code argument", argv[4]);
if (!ToInt(argv[3], out_exit_code)) {
LogErrorWithArg(__LINE__, "Failed to parse exit code argument", argv[3]);
return false;
}
return true;
Expand Down Expand Up @@ -1516,7 +1511,7 @@ bool TeeImpl::MainFunc() const {
}

int RunSubprocess(const Path& test_path, const std::wstring& args,
const Path& test_outerr, Duration* test_duration) {
const Path& test_outerr) {
std::unique_ptr<Tee> tee;
bazel::windows::WaitableProcess process;
LARGE_INTEGER start, end, freq;
Expand All @@ -1539,17 +1534,6 @@ int RunSubprocess(const Path& test_path, const std::wstring& args,
return 1;
}

QueryPerformanceFrequency(&freq);
end.QuadPart -= start.QuadPart;
decltype(LARGE_INTEGER::QuadPart) seconds;
// Compute the number of seconds the test ran for.
seconds = end.QuadPart / freq.QuadPart;
// Check the remainder: if it's at least 0.5 seconds, round up.
if ((end.QuadPart - seconds * freq.QuadPart) * 2 >= freq.QuadPart) {
seconds += 1;
}
test_duration->seconds =
(seconds > Duration::kMax) ? Duration::kMax : seconds;
return result;
}

Expand Down Expand Up @@ -1686,7 +1670,7 @@ std::string CreateErrorTag(int exit_code) {
}

bool CreateXmlLog(const Path& output, const Path& test_outerr,
const Duration duration, const int exit_code,
const int exit_code,
const DeleteAfterwards delete_afterwards,
const MainType main_type) {
if (main_type != MainType::kXmlWriterMain) {
Expand Down Expand Up @@ -1743,8 +1727,7 @@ bool CreateXmlLog(const Path& output, const Path& test_outerr,
<< acp_test_name << "\" tests=\"1\" failures=\"0\" errors=\"" << errors
<< "\">\n"
"<testcase name=\""
<< acp_test_name << "\" status=\"run\" duration=\"" << duration.seconds
<< "\" time=\"" << duration.seconds << "\">" << error_msg
<< acp_test_name << "\" status=\"run\">" << error_msg
<< "</testcase>\n"
"<system-out><![CDATA[";
if (!ostm.good()) {
Expand Down Expand Up @@ -1953,9 +1936,8 @@ int TestWrapperMain(int argc, wchar_t** argv) {
return 1;
}

Duration test_duration;
int result = RunSubprocess(executable, args, test_outerr, &test_duration);
if (!CreateXmlLog(xml_log, test_outerr, test_duration, result,
int result = RunSubprocess(executable, args, test_outerr);
if (!CreateXmlLog(xml_log, test_outerr, result,
DeleteAfterwards::kEnabled, MainType::kTestWrapperMain) ||
!ArchiveUndeclaredOutputs(undecl) ||
!CreateUndeclaredOutputsAnnotations(undecl.annotations_dir,
Expand All @@ -1967,13 +1949,12 @@ int TestWrapperMain(int argc, wchar_t** argv) {

int XmlWriterMain(int argc, wchar_t** argv) {
Path cwd, test_outerr, test_xml_log;
Duration duration;
int exit_code = 0;

if (!GetCwd(&cwd) ||
!ParseXmlWriterArgs(argc, argv, cwd, &test_outerr, &test_xml_log,
&duration, &exit_code) ||
!CreateXmlLog(test_xml_log, test_outerr, duration, exit_code,
&exit_code) ||
!CreateXmlLog(test_xml_log, test_outerr, exit_code,
DeleteAfterwards::kDisabled, MainType::kXmlWriterMain)) {
return 1;
}
Expand Down