You are viewing a plain text version of this content. The canonical link for it is here.
Posted to github@trafficserver.apache.org by "bneradt (via GitHub)" <gi...@apache.org> on 2026/08/12 22:13:31 UTC
[PR] AuTest timing improvements [trafficserver]
bneradt opened a new pull request, #13540:
URL: https://github.com/apache/trafficserver/pull/13540
Parallel AuTest runs were repeating similarly named tests, while timing
collection reset shared port allocation by starting a process per test.
Several tests also waited on client defaults, retries, and log buffering
rather than behavior under verification.
Exact test selection
--------------------
The runner now anchors worker filters to test paths. This avoids suffix
collisions, duplicate runs, and parallel execution of serial tests.
Batch timing collection
-----------------------
The runner now measures completions from persistent worker batches. This
preserves shared port allocation and removes per-test process startup.
Rate-limit expiration
---------------------
The rate-limit test bounds the queued client wait and requires the ATS
expiration diagnostic, retaining queue-expiration coverage.
Server-abort timeouts
---------------------
The server-abort test disables retries and shortens connection and
inactivity timeouts that are unrelated to the expected abort.
JAX fingerprint log flushing
----------------------------
The JAX fingerprint test flushes log buffers once per second so its
existing log assertions do not wait on production buffering defaults.
Stale-response log flushing
---------------------------
The stale-response test similarly flushes logs once per second while
retaining its existing traffic and log assertions.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "bneradt (via GitHub)" <gi...@apache.org>.
bneradt merged PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "bneradt (via GitHub)" <gi...@apache.org>.
bneradt commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3908447425
##########
tests/autest-parallel.py.in:
##########
@@ -227,6 +241,46 @@ def strip_ansi(text: str) -> str:
return ansi_escape.sub('', text)
+def parse_test_completion(line: str) -> Optional[Tuple[str, str]]:
+ """Extract a completed test name and status from an autest progress line."""
+ clean = strip_ansi(line).strip()
+ marker = 'Running Test '
+ marker_pos = clean.rfind(marker)
+
+ if marker_pos < 0:
+ return None
+
+ completion = clean[marker_pos + len(marker):]
+ match = re.match(rf'([^:\s]+):.*\b({TERMINAL_STATUS_PATTERN})\s*$', completion, re.IGNORECASE)
+ if not match:
+ return None
+
+ return match.group(1), match.group(2).upper()
Review Comment:
Addressed in b23670b907. `parse_test_completion()` now accepts both streamed `Running Test <name>: ... <status>` lines and summary-style `Test: <name>: ... <status>` lines. Targeted parser assertions cover both forms, and a timing-aware `cache-control` AuTest recorded the completion and passed.
##########
tests/autest-parallel.py.in:
##########
@@ -39,12 +39,26 @@ from concurrent.futures import ProcessPoolExecutor, as_completed
from dataclasses import dataclass, field
from datetime import datetime
from pathlib import Path
-from typing import Dict, List, Optional, Tuple
+from queue import Empty, Queue
+from threading import Thread
+from typing import Dict, List, Optional, TextIO, Tuple
# Default serial tests file location
DEFAULT_SERIAL_TESTS_FILE = Path("${CMAKE_CURRENT_SOURCE_DIR}") / "serial_tests.txt"
# Default estimate for unknown tests (seconds)
DEFAULT_TEST_TIME = 15.0
+# Maximum time between completed tests in a worker batch.
+PER_TEST_TIMEOUT = 600.0
Review Comment:
Addressed in b23670b907. `PER_TEST_TIMEOUT` is now 3600 seconds, aligned with the existing non-streamed worker timeout. The timing path still resets that allowance after each test completion, so collecting timings no longer imposes the former 10-minute behavioral cap.
##########
tests/autest-parallel.py.in:
##########
@@ -433,7 +487,7 @@ def run_single_test(test: str, script_dir: Path, sandbox: Path, ats_bin: str, bu
cmd = [
'uv', 'run', 'autest', 'run', '--directory', '${CMAKE_GOLD_DIR}', '--ats-bin', ats_bin, '--proxy-verifier-bin',
'${PROXY_VERIFIER_PATH}', '--build-root', build_root, '--sandbox',
- str(sandbox / test), '--filters', test
+ str(sandbox / test), '--filters', f'/{test}'
Review Comment:
I checked the AuTest 1.10.6 scanner behavior: it prepends `*` when needed and passes the resulting pattern to `fnmatch`, but it does not append a wildcard. Thus `/rate_limit` becomes `*/rate_limit`, which matches the exact path suffix and does not match `rate_limit_sni`. I also verified those two cases directly, so no code change is needed here.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "moonchen (via GitHub)" <gi...@apache.org>.
moonchen commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3898261964
##########
tests/autest-parallel.py.in:
##########
@@ -227,6 +227,37 @@ def strip_ansi(text: str) -> str:
return ansi_escape.sub('', text)
+def parse_test_completion(line: str) -> Optional[Tuple[str, str]]:
+ """Extract a completed test name and status from an autest progress line."""
+ clean = strip_ansi(line).strip()
+ marker = 'Running Test '
+ marker_pos = clean.rfind(marker)
+
+ if marker_pos < 0:
+ return None
+
+ completion = clean[marker_pos + len(marker):]
+ match = re.match(r'([^:\s]+):.*\b(Passed|Failed|Skipped)\s*$', completion, re.IGNORECASE)
Review Comment:
AuTest 1.10.6 can finish a test as Unknown, Skipped, Passed, Warning, Failed, or Exception, but this regex and parse_detached_test_status accept only three. When Warning, Exception, or Unknown is skipped, last_completion is not advanced, so that test runtime is added to the next recognized test and the corrupted duration is saved for future partitioning. Please recognize all terminal statuses here and update short_status accordingly.
##########
tests/autest-parallel.py.in:
##########
@@ -517,151 +548,150 @@ def run_worker(
existing = env.get('PYTHONPATH', '')
env['PYTHONPATH'] = ':'.join(pythonpath_dirs + ([existing] if existing else []))
- if collect_timings:
- # Run tests one at a time to collect accurate timing
- all_output = []
- total_tests = len(tests)
- try:
- for idx, test in enumerate(tests, 1):
- test_name, duration, status, output = run_single_test(
- test, script_dir, sandbox, ats_bin, build_root, extra_args, env)
- result.test_timings[test_name] = duration
- all_output.append(output)
-
- if status == "PASS":
- result.passed += 1
- elif status == "SKIP":
- result.skipped += 1
- else:
- result.failed += 1
- result.failed_tests.append(test_name)
+ # Keep all tests in one autest process so its shared port queue is not
+ # reset between tests. This is both faster and avoids reusing ports that a
+ # recently completed test may still hold.
+ cmd = [
+ 'uv',
+ 'run',
+ 'autest',
+ 'run',
+ '--directory',
+ '${CMAKE_GOLD_DIR}',
+ '--ats-bin',
+ ats_bin,
+ '--proxy-verifier-bin',
+ '${PROXY_VERIFIER_PATH}',
+ '--build-root',
+ build_root,
+ '--sandbox',
+ str(sandbox),
+ '--filters',
+ ]
+ cmd.extend(f'/{test}' for test in tests)
+ cmd.extend(extra_args)
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- # Fixed-width format: date time status duration worker progress test_name
- print(
- f"{timestamp} {status:4s} {duration:6.1f}s Worker:{worker_id:2d} {idx:2d}/{total_tests:2d} {test}", flush=True)
- except KeyboardInterrupt:
- result.return_code = 130
+ timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
+ print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
+ if verbose:
+ print(
+ f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
+ f"{'...' if len(tests) > 5 else ''}",
+ flush=True)
- result.output = "\n".join(all_output)
- if result.return_code != 130:
- result.return_code = 0 if result.failed == 0 else 1
- else:
- # Run all tests in batch (faster but no per-test timing)
- cmd = [
- 'uv',
- 'run',
- 'autest',
- 'run',
- '--directory',
- '${CMAKE_GOLD_DIR}',
- '--ats-bin',
- ats_bin,
- '--proxy-verifier-bin',
- '${PROXY_VERIFIER_PATH}',
- '--build-root',
- build_root,
- '--sandbox',
- str(sandbox),
- ]
-
- # Add test filters
- cmd.append('--filters')
- cmd.extend(tests)
-
- # Add any extra arguments
- cmd.extend(extra_args)
-
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
- if verbose:
- print(
- f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
- f"{'...' if len(tests) > 5 else ''}",
- flush=True)
+ try:
+ if verbose or collect_timings:
+ # Autest flushes each completed test line. Observe those lines to
+ # collect timings without changing how autest executes the batch.
+ proc = subprocess.Popen(
+ cmd,
+ cwd=script_dir,
+ stdout=subprocess.PIPE,
+ stderr=subprocess.STDOUT,
+ text=True,
+ env=env,
+ )
+ output_lines = []
+ last_completion = time.monotonic()
+ completed_count = 0
+ pending_test = None
+ try:
+ for line in proc.stdout:
Review Comment:
The timeout below only starts after stdout reaches EOF. If a test wedges while keeping the pipe open, this blocking iteration never finishes; collect-timings has therefore lost the previous 600-second per-test bound, and as_completed waits forever as well. Please enforce a wall-clock timeout while consuming stdout and terminate the child when it expires.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "Copilot (via GitHub)" <gi...@apache.org>.
Copilot commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3908055042
##########
tests/autest-parallel.py.in:
##########
@@ -433,7 +487,7 @@ def run_single_test(test: str, script_dir: Path, sandbox: Path, ats_bin: str, bu
cmd = [
'uv', 'run', 'autest', 'run', '--directory', '${CMAKE_GOLD_DIR}', '--ats-bin', ats_bin, '--proxy-verifier-bin',
'${PROXY_VERIFIER_PATH}', '--build-root', build_root, '--sandbox',
- str(sandbox / test), '--filters', test
+ str(sandbox / test), '--filters', f'/{test}'
Review Comment:
Using f'/{test}' as an autest filter can still match multiple tests when one test name is a prefix of another (e.g., rate_limit matches rate_limit_sni). This risks reintroducing duplicate/incorrect test selection in parallel runs.
This issue also appears on line 592 of the same file.
##########
tests/autest-parallel.py.in:
##########
@@ -39,12 +39,26 @@ from concurrent.futures import ProcessPoolExecutor, as_completed
from dataclasses import dataclass, field
from datetime import datetime
from pathlib import Path
-from typing import Dict, List, Optional, Tuple
+from queue import Empty, Queue
+from threading import Thread
+from typing import Dict, List, Optional, TextIO, Tuple
# Default serial tests file location
DEFAULT_SERIAL_TESTS_FILE = Path("${CMAKE_CURRENT_SOURCE_DIR}") / "serial_tests.txt"
# Default estimate for unknown tests (seconds)
DEFAULT_TEST_TIME = 15.0
+# Maximum time between completed tests in a worker batch.
+PER_TEST_TIMEOUT = 600.0
Review Comment:
PER_TEST_TIMEOUT introduces a hard 600s cap between test completions when running with -v/--collect-timings, which can terminate legitimately slow tests and changes behavior compared to the 1h worker timeout used in the non-verbose path.
##########
tests/autest-parallel.py.in:
##########
@@ -227,6 +241,46 @@ def strip_ansi(text: str) -> str:
return ansi_escape.sub('', text)
+def parse_test_completion(line: str) -> Optional[Tuple[str, str]]:
+ """Extract a completed test name and status from an autest progress line."""
+ clean = strip_ansi(line).strip()
+ marker = 'Running Test '
+ marker_pos = clean.rfind(marker)
+
+ if marker_pos < 0:
+ return None
+
+ completion = clean[marker_pos + len(marker):]
+ match = re.match(rf'([^:\s]+):.*\b({TERMINAL_STATUS_PATTERN})\s*$', completion, re.IGNORECASE)
+ if not match:
+ return None
+
+ return match.group(1), match.group(2).upper()
Review Comment:
parse_test_completion() only recognizes progress lines starting with "Running Test <name>:". Elsewhere in this same file, parse_autest_output() expects autest to emit completion lines like "Test: <name>: Passed/Failed", so timing collection can miss completions, never reset the timeout, and fail to produce per-test timings.
This issue also appears on line 261 of the same file.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "bneradt (via GitHub)" <gi...@apache.org>.
bneradt commented on PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#issuecomment-5514241850
[approve ci autest]
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "Copilot (via GitHub)" <gi...@apache.org>.
Copilot commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3908501157
##########
tests/autest-parallel.py.in:
##########
@@ -517,151 +574,181 @@ def run_worker(
existing = env.get('PYTHONPATH', '')
env['PYTHONPATH'] = ':'.join(pythonpath_dirs + ([existing] if existing else []))
- if collect_timings:
- # Run tests one at a time to collect accurate timing
- all_output = []
- total_tests = len(tests)
- try:
- for idx, test in enumerate(tests, 1):
- test_name, duration, status, output = run_single_test(
- test, script_dir, sandbox, ats_bin, build_root, extra_args, env)
- result.test_timings[test_name] = duration
- all_output.append(output)
-
- if status == "PASS":
- result.passed += 1
- elif status == "SKIP":
- result.skipped += 1
- else:
- result.failed += 1
- result.failed_tests.append(test_name)
+ # Keep all tests in one autest process so its shared port queue is not
+ # reset between tests. This is both faster and avoids reusing ports that a
+ # recently completed test may still hold.
+ cmd = [
+ 'uv',
+ 'run',
+ 'autest',
+ 'run',
+ '--directory',
+ '${CMAKE_GOLD_DIR}',
+ '--ats-bin',
+ ats_bin,
+ '--proxy-verifier-bin',
+ '${PROXY_VERIFIER_PATH}',
+ '--build-root',
+ build_root,
+ '--sandbox',
+ str(sandbox),
+ '--filters',
+ ]
+ cmd.extend(f'/{test}' for test in tests)
+ cmd.extend(extra_args)
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- # Fixed-width format: date time status duration worker progress test_name
- print(
- f"{timestamp} {status:4s} {duration:6.1f}s Worker:{worker_id:2d} {idx:2d}/{total_tests:2d} {test}", flush=True)
- except KeyboardInterrupt:
- result.return_code = 130
+ timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
+ print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
+ if verbose:
+ print(
+ f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
+ f"{'...' if len(tests) > 5 else ''}",
+ flush=True)
- result.output = "\n".join(all_output)
- if result.return_code != 130:
- result.return_code = 0 if result.failed == 0 else 1
- else:
- # Run all tests in batch (faster but no per-test timing)
- cmd = [
- 'uv',
- 'run',
- 'autest',
- 'run',
- '--directory',
- '${CMAKE_GOLD_DIR}',
- '--ats-bin',
- ats_bin,
- '--proxy-verifier-bin',
- '${PROXY_VERIFIER_PATH}',
- '--build-root',
- build_root,
- '--sandbox',
- str(sandbox),
- ]
-
- # Add test filters
- cmd.append('--filters')
- cmd.extend(tests)
-
- # Add any extra arguments
- cmd.extend(extra_args)
-
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
- if verbose:
- print(
- f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
- f"{'...' if len(tests) > 5 else ''}",
- flush=True)
+ try:
+ if verbose or collect_timings:
+ # Autest flushes each completed test line. Observe those lines to
+ # collect timings without changing how autest executes the batch.
+ proc = subprocess.Popen(
+ cmd,
+ cwd=script_dir,
+ stdout=subprocess.PIPE,
+ stderr=subprocess.STDOUT,
+ text=True,
+ env=env,
+ )
+ output_lines = []
+ output_queue: Queue[Optional[str]] = Queue()
+ output_reader = Thread(target=enqueue_process_output, args=(proc.stdout, output_queue), daemon=True)
+ output_reader.start()
+ last_completion = time.monotonic()
+ completed_count = 0
+ pending_test = None
+ timed_out = False
+ try:
+ while True:
+ remaining = PER_TEST_TIMEOUT - (time.monotonic() - last_completion)
+ if remaining <= 0:
+ timed_out = True
+ break
- try:
- if verbose:
- # Stream output in real-time so the user sees test progress.
- # We use Popen + line-by-line read so partial results are visible
- # even if the overall run takes a long time.
- proc = subprocess.Popen(
- cmd,
- cwd=script_dir,
- stdout=subprocess.PIPE,
- stderr=subprocess.STDOUT,
- text=True,
- env=env,
- )
- output_lines = []
- try:
- for line in proc.stdout:
- output_lines.append(line)
- # Print lines that show test progress
- clean = strip_ansi(line).strip()
- if clean.startswith('Running Test') or 'Passed' in clean or 'Failed' in clean:
- if clean.startswith('Running Test'):
- ts = datetime.now().strftime("%H:%M:%S")
- print(f" [{ts}] Worker:{worker_id:2d} {clean}", flush=True)
- # stdout is exhausted, wait for process to finish
+ try:
+ line = output_queue.get(timeout=min(1.0, remaining))
+ except Empty:
+ continue
+
+ if line is None:
+ break
+
+ output_lines.append(line)
+ started_test = parse_test_start(line)
+ if started_test is not None:
+ pending_test = started_test
+ completion = parse_test_completion(line)
+ if completion is None and pending_test is not None:
+ status = parse_detached_test_status(line)
+ if status is not None:
+ completion = pending_test, status
+ if completion is None:
+ continue
+
+ test_name, status = completion
+ pending_test = None
+ now = time.monotonic()
+ duration = now - last_completion
+ last_completion = now
Review Comment:
The first recorded timing currently includes autest process startup/scanning time because last_completion is initialized before any test starts and durations are computed from last_completion. Since the timings file is used for LPT load balancing, this can systematically overestimate whichever test happens to be first in each worker batch. A low-risk improvement is to reset last_completion when the first test start marker is observed (only when the line is a start, not a completion), so the first duration measures from that test’s start rather than from process launch.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "bneradt (via GitHub)" <gi...@apache.org>.
bneradt commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3908004515
##########
tests/autest-parallel.py.in:
##########
@@ -227,6 +227,37 @@ def strip_ansi(text: str) -> str:
return ansi_escape.sub('', text)
+def parse_test_completion(line: str) -> Optional[Tuple[str, str]]:
+ """Extract a completed test name and status from an autest progress line."""
+ clean = strip_ansi(line).strip()
+ marker = 'Running Test '
+ marker_pos = clean.rfind(marker)
+
+ if marker_pos < 0:
+ return None
+
+ completion = clean[marker_pos + len(marker):]
+ match = re.match(r'([^:\s]+):.*\b(Passed|Failed|Skipped)\s*$', completion, re.IGNORECASE)
Review Comment:
Fixed in 483ffc8c28. Timing completion parsing now accepts Unknown, Skipped, Passed, Warning, Failed, and Exception in both combined and detached output, with stable short labels for all six. This keeps last_completion and saved per-test timings aligned for every terminal state.
##########
tests/autest-parallel.py.in:
##########
@@ -517,151 +548,150 @@ def run_worker(
existing = env.get('PYTHONPATH', '')
env['PYTHONPATH'] = ':'.join(pythonpath_dirs + ([existing] if existing else []))
- if collect_timings:
- # Run tests one at a time to collect accurate timing
- all_output = []
- total_tests = len(tests)
- try:
- for idx, test in enumerate(tests, 1):
- test_name, duration, status, output = run_single_test(
- test, script_dir, sandbox, ats_bin, build_root, extra_args, env)
- result.test_timings[test_name] = duration
- all_output.append(output)
-
- if status == "PASS":
- result.passed += 1
- elif status == "SKIP":
- result.skipped += 1
- else:
- result.failed += 1
- result.failed_tests.append(test_name)
+ # Keep all tests in one autest process so its shared port queue is not
+ # reset between tests. This is both faster and avoids reusing ports that a
+ # recently completed test may still hold.
+ cmd = [
+ 'uv',
+ 'run',
+ 'autest',
+ 'run',
+ '--directory',
+ '${CMAKE_GOLD_DIR}',
+ '--ats-bin',
+ ats_bin,
+ '--proxy-verifier-bin',
+ '${PROXY_VERIFIER_PATH}',
+ '--build-root',
+ build_root,
+ '--sandbox',
+ str(sandbox),
+ '--filters',
+ ]
+ cmd.extend(f'/{test}' for test in tests)
+ cmd.extend(extra_args)
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- # Fixed-width format: date time status duration worker progress test_name
- print(
- f"{timestamp} {status:4s} {duration:6.1f}s Worker:{worker_id:2d} {idx:2d}/{total_tests:2d} {test}", flush=True)
- except KeyboardInterrupt:
- result.return_code = 130
+ timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
+ print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
+ if verbose:
+ print(
+ f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
+ f"{'...' if len(tests) > 5 else ''}",
+ flush=True)
- result.output = "\n".join(all_output)
- if result.return_code != 130:
- result.return_code = 0 if result.failed == 0 else 1
- else:
- # Run all tests in batch (faster but no per-test timing)
- cmd = [
- 'uv',
- 'run',
- 'autest',
- 'run',
- '--directory',
- '${CMAKE_GOLD_DIR}',
- '--ats-bin',
- ats_bin,
- '--proxy-verifier-bin',
- '${PROXY_VERIFIER_PATH}',
- '--build-root',
- build_root,
- '--sandbox',
- str(sandbox),
- ]
-
- # Add test filters
- cmd.append('--filters')
- cmd.extend(tests)
-
- # Add any extra arguments
- cmd.extend(extra_args)
-
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
- if verbose:
- print(
- f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
- f"{'...' if len(tests) > 5 else ''}",
- flush=True)
+ try:
+ if verbose or collect_timings:
+ # Autest flushes each completed test line. Observe those lines to
+ # collect timings without changing how autest executes the batch.
+ proc = subprocess.Popen(
+ cmd,
+ cwd=script_dir,
+ stdout=subprocess.PIPE,
+ stderr=subprocess.STDOUT,
+ text=True,
+ env=env,
+ )
+ output_lines = []
+ last_completion = time.monotonic()
+ completed_count = 0
+ pending_test = None
+ try:
+ for line in proc.stdout:
Review Comment:
Fixed in 483ffc8c28. Worker stdout is now read into a queue by a daemon reader while the worker enforces a 600-second deadline between completed tests. On expiry it terminates and, if needed, kills the child and records a TIMEOUT diagnostic. I also exercised the timeout path with a reduced deadline and ran a two-worker collect-timings AuTest successfully.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org
Re: [PR] AuTest timing improvements [trafficserver]
Posted by "bneradt (via GitHub)" <gi...@apache.org>.
bneradt commented on code in PR #13540:
URL: https://github.com/apache/trafficserver/pull/13540#discussion_r3909175758
##########
tests/autest-parallel.py.in:
##########
@@ -517,151 +574,181 @@ def run_worker(
existing = env.get('PYTHONPATH', '')
env['PYTHONPATH'] = ':'.join(pythonpath_dirs + ([existing] if existing else []))
- if collect_timings:
- # Run tests one at a time to collect accurate timing
- all_output = []
- total_tests = len(tests)
- try:
- for idx, test in enumerate(tests, 1):
- test_name, duration, status, output = run_single_test(
- test, script_dir, sandbox, ats_bin, build_root, extra_args, env)
- result.test_timings[test_name] = duration
- all_output.append(output)
-
- if status == "PASS":
- result.passed += 1
- elif status == "SKIP":
- result.skipped += 1
- else:
- result.failed += 1
- result.failed_tests.append(test_name)
+ # Keep all tests in one autest process so its shared port queue is not
+ # reset between tests. This is both faster and avoids reusing ports that a
+ # recently completed test may still hold.
+ cmd = [
+ 'uv',
+ 'run',
+ 'autest',
+ 'run',
+ '--directory',
+ '${CMAKE_GOLD_DIR}',
+ '--ats-bin',
+ ats_bin,
+ '--proxy-verifier-bin',
+ '${PROXY_VERIFIER_PATH}',
+ '--build-root',
+ build_root,
+ '--sandbox',
+ str(sandbox),
+ '--filters',
+ ]
+ cmd.extend(f'/{test}' for test in tests)
+ cmd.extend(extra_args)
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- # Fixed-width format: date time status duration worker progress test_name
- print(
- f"{timestamp} {status:4s} {duration:6.1f}s Worker:{worker_id:2d} {idx:2d}/{total_tests:2d} {test}", flush=True)
- except KeyboardInterrupt:
- result.return_code = 130
+ timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
+ print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
+ if verbose:
+ print(
+ f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
+ f"{'...' if len(tests) > 5 else ''}",
+ flush=True)
- result.output = "\n".join(all_output)
- if result.return_code != 130:
- result.return_code = 0 if result.failed == 0 else 1
- else:
- # Run all tests in batch (faster but no per-test timing)
- cmd = [
- 'uv',
- 'run',
- 'autest',
- 'run',
- '--directory',
- '${CMAKE_GOLD_DIR}',
- '--ats-bin',
- ats_bin,
- '--proxy-verifier-bin',
- '${PROXY_VERIFIER_PATH}',
- '--build-root',
- build_root,
- '--sandbox',
- str(sandbox),
- ]
-
- # Add test filters
- cmd.append('--filters')
- cmd.extend(tests)
-
- # Add any extra arguments
- cmd.extend(extra_args)
-
- timestamp = datetime.now().strftime("%Y-%m-%d %H:%M:%S")
- print(f"{timestamp} Worker:{worker_id:2d} Starting batch of {len(tests)} tests (port offset {port_offset})", flush=True)
- if verbose:
- print(
- f" Worker:{worker_id:2d} Tests: {', '.join(tests[:5])}"
- f"{'...' if len(tests) > 5 else ''}",
- flush=True)
+ try:
+ if verbose or collect_timings:
+ # Autest flushes each completed test line. Observe those lines to
+ # collect timings without changing how autest executes the batch.
+ proc = subprocess.Popen(
+ cmd,
+ cwd=script_dir,
+ stdout=subprocess.PIPE,
+ stderr=subprocess.STDOUT,
+ text=True,
+ env=env,
+ )
+ output_lines = []
+ output_queue: Queue[Optional[str]] = Queue()
+ output_reader = Thread(target=enqueue_process_output, args=(proc.stdout, output_queue), daemon=True)
+ output_reader.start()
+ last_completion = time.monotonic()
+ completed_count = 0
+ pending_test = None
+ timed_out = False
+ try:
+ while True:
+ remaining = PER_TEST_TIMEOUT - (time.monotonic() - last_completion)
+ if remaining <= 0:
+ timed_out = True
+ break
- try:
- if verbose:
- # Stream output in real-time so the user sees test progress.
- # We use Popen + line-by-line read so partial results are visible
- # even if the overall run takes a long time.
- proc = subprocess.Popen(
- cmd,
- cwd=script_dir,
- stdout=subprocess.PIPE,
- stderr=subprocess.STDOUT,
- text=True,
- env=env,
- )
- output_lines = []
- try:
- for line in proc.stdout:
- output_lines.append(line)
- # Print lines that show test progress
- clean = strip_ansi(line).strip()
- if clean.startswith('Running Test') or 'Passed' in clean or 'Failed' in clean:
- if clean.startswith('Running Test'):
- ts = datetime.now().strftime("%H:%M:%S")
- print(f" [{ts}] Worker:{worker_id:2d} {clean}", flush=True)
- # stdout is exhausted, wait for process to finish
+ try:
+ line = output_queue.get(timeout=min(1.0, remaining))
+ except Empty:
+ continue
+
+ if line is None:
+ break
+
+ output_lines.append(line)
+ started_test = parse_test_start(line)
+ if started_test is not None:
+ pending_test = started_test
+ completion = parse_test_completion(line)
+ if completion is None and pending_test is not None:
+ status = parse_detached_test_status(line)
+ if status is not None:
+ completion = pending_test, status
+ if completion is None:
+ continue
+
+ test_name, status = completion
+ pending_test = None
+ now = time.monotonic()
+ duration = now - last_completion
+ last_completion = now
Review Comment:
Addressed in `4ee4b62d83`.
The timing path now resets `last_completion` when it observes the first genuine test-start line. It parses completion status first and requires that the same line is not already a completion, so combined `Running Test ... Passed` output cannot collapse the first duration to zero. A one-shot guard prevents duplicate start markers from resetting the clock again. Later tests still measure from the previous completion.
Validation in `asfats5`:
- Format, full build, and install passed.
- The timing-aware `cache-control` AuTest passed and recorded its first-test duration as 40.2 seconds.
--
This is an automated message from the Apache Git Service.
To respond to the message, please log on to GitHub and use the
URL above to go to the specific comment.
To unsubscribe, e-mail: github-unsubscribe@trafficserver.apache.org
For queries about this service, please contact Infrastructure at:
users@infra.apache.org