[merlimat]

Motivation

The four forks of a unit test group's test task finish far apart. In the scheduled master run of 2 Nov 12:18 UTC:

Job	Forks (s)	Longest	If balanced
Broker Group 1 (the longest CI job, 30.4 min)	1722 / 1249 / 1043 / 1038	28.7 min	21.1 min
Pulsar Metadata	1067 / 314 / 280 / 213	17.8 min	7.8 min
Client Impl	951 / 816 / 660 / 398	15.8 min	11.8 min
Client Api	852 / 726 / 385 / 288	14.2 min	9.4 min

Gradle's Test task deals its test classes to its forks round-robin, before any of them runs, so how busy a fork
is never matters (Gradle 9.8.2 bytecode):

• MaxNParallelTestDefinitionProcessor.processTestDefinition creates up to maxParallelForks processors, then does
  processors.get(pos); pos = (pos + 1) % size.
• In the fork, TestNGTestDefinitionProcessor.processTestDefinition only adds the class to a list, and stop() runs
  them all in one TestNG run.
• The classes come in scan order. DefaultTestScanner's visitor asks for a reproducible file order
  (ReproducibleDirectoryWalker, files before sub-packages, each sorted by name).
• Every test class of the module takes a slot, because -PtestGroups is applied inside the forks.

So which fork a slow class lands on depends on the names of all the module's test classes, and adding, removing or
renaming one moves every class after it to the next fork.

For example, on 31 Oct 43f1ce1 added org.apache.bookkeeper.replication.ParallelAuditorShutdownTest. It sorts
before TestReplicationWorker and every org.apache.pulsar.metadata.* class, so each of those moved one fork along.
Round-robin over the scan order reproduces the executor of every Pulsar Metadata class in both runs' build scans
(counting MetadataBenchmark, whose tests are all enabled = false: it takes a slot and reports nothing). Seconds
from each run:

Fork	30 Oct (before)	2 Nov (after)
1	TestReplicationWorker 139, MetadataStoreTableViewTest 99, LedgerUnderreplicationManagerTest 244, ...: 588 s	LedgerManagerIteratorTest 74, ...: 267 s
2	AuditorBookieTest 247, AuditorPeriodicCheckTest 309, BookieAutoRecoveryTest 144, ...: 778 s	AuditorBookieTest 64, AuditorPeriodicCheckTest 296, BookieAutoRecoveryTest 144, TestReplicationWorker 134, MetadataStoreTableViewTest 98, LedgerUnderreplicationManagerTest 241, ...: 1053 s
3	AuditorRollingRestartTest 76, ...: 190 s	AuditorRollingRestartTest 106, ...: 199 s
4	AuditorLedgerCheckerTest 311, LedgerManagerIteratorTest 83, ...: 602 s	AuditorLedgerCheckerTest 188, ...: 300 s

That commit saved 3 min of AuditorBookieTest, but the job got 4.6 min longer: 13.0 → 17.6 min, while its balanced
time fell from 9.0 to 7.6 min.

Modifications

• pulsar.java-conventions: with -PtestShards=N and -PtestShardDurations=<file> (lines of
  <seconds> <class name>), testShards runs testShard1 .. testShardN. These are test tasks with one fork each,
  configured like test by the existing withType<Test> blocks.
  • The classes in the file are packed longest-first (LPT). Any other class goes by a hash of its name, and a nested
    class goes with its top-level class.
  • The split is an exclude spec on the test class files, so every class file reaches exactly one shard.
  • The shards share FailFastNotifier's existing kill-switch file (testFailFastFile). With testFailFast (PR
    runs), a failure in one shard skips the others' remaining tests, as one test task stops all its forks today.
  • Without recorded durations, testShards just runs test, as before.
  • The plain test task is unchanged.
• run_unit_group_gradle.sh: the nine groups whose test task had 4 forks (Broker Groups 1, 2, 3 and 5, Client Api,
  Client Impl, Pulsar Client, Pulsar Metadata, Proxy) run testShards with --configuration-cache. Gradle runs tasks
  of one project in parallel only with the configuration cache. Measured on 9.8.2: two test tasks of one project ran
  one after the other without it, and at once with it.
  • After a successful run, the script records the durations for the group's next run.
  • Broker Group 4, the flaky groups, the isolated classes of Groups 1 and 3, and OTHER, Pulsar IO and Protobuf v3 are
    unchanged.
• pulsar_ci_tool.sh:
  • record_test_durations writes the durations from the JUnit XML reports. A report's time ends with the class's
    last test method, before its cleanup, but a shard runs its classes one after the other in one JVM. So in a shard,
    a class lasts until the next class starts. For example, locally AuditorRollingRestartTest reports 36 s but
    takes 107 s; the build scan's 106 s on CI matches the 107 s.
  • The forks of test share one report directory, so that run (the first one only) records the reports' times.
  • A nested class counts toward its top-level class.
  • generate_test_report_index also lists the shards' HTML reports.
• pulsar-ci.yaml: the unit-tests job restores the newest unit-test-durations-<group>-* cache entry before the
  tests, and saves this run's durations after a successful run. Master runs feed every PR, and a PR's runs feed its
  later runs.
• CONTRIBUTING.md: describes the two properties.

Verifying this change

• Make sure that the change passes the CI checks.

Same classes. For each of the nine groups, I ran TestNG dry runs (dryRun = true, set by an init script) of test
and of testShards, and compared the classes in the JUnit XML reports. I ran testShards both with the durations from
the 2 Nov 12:18 build scans and with every class split by hash. In every case the shards ran the same classes as
test, and no class ran in two shards:

Group	Classes	Per shard, with durations	Per shard, all by hash
Broker Group 1	294	74 / 73 / 74 / 73	69 / 72 / 77 / 76
Broker Group 2	311	75 / 78 / 79 / 79	83 / 77 / 84 / 67
Broker Group 3	65	15 / 17 / 17 / 16	19 / 15 / 16 / 15
Broker Group 5	35	5 / 10 / 10 / 10	9 / 9 / 9 / 8
Client Api	82	20 / 21 / 21 / 20	22 / 24 / 13 / 23
Client Impl	80	20 / 20 / 20 / 20	27 / 13 / 24 / 16
Pulsar Client	168	42 / 42 / 42 / 42	40 / 28 / 49 / 51
Pulsar Metadata	74	19 / 18 / 19 / 18	17 / 20 / 21 / 16
Proxy	62	15 / 14 / 16 / 17	10 / 14 / 13 / 25

The test counts match too, except for one class. Under test, the nested SchemaInfoTest$SchemaInfoBuilderTest ran
its 3 tests twice (Pulsar Client: 1288 tests against the shards' 1285). TestNG runs a public static nested test
class along with its outer class, and only skips the duplicate when both are in the same JVM. Round-robin put the two
on different forks: with --tests 'org.apache.pulsar.client.impl.schema.SchemaInfoTest*', the nested class reports
3 test cases with 1 fork and 6 with 2. The shards keep a nested class with its top-level class, so it runs once.

Local timing, Pulsar Metadata. All tests passed in every run. Two pairs, back to back, on a busy shared Mac:

	test (4 forks, round-robin)	testShards (packed on the CI durations)	Shard spans
Pair 1	1059 s	481 s	401 / 477 / 455 / 409 s
Pair 2	1000 s	508 s	453 / 478 / 505 / 435 s

The CI script end to end. I ran run_unit_group_gradle.sh METADATA twice, with a scheduled run's environment, a
dry-run init script and an empty durations directory.

• The first run had no durations, so testShards ran test, and the script recorded the durations.
• The second run ran testShard1..4 with those durations, and recorded again from the shards.

Other checks.

• The recorder gives the same results under macOS's BSD tools and the busybox tools of the Pulsar test image, and on
  synthetic reports with a nested class and a run across midnight UTC.
• A reused configuration-cache entry splits the classes the same way as a freshly stored one.
• No new findings from actionlint on pulsar-ci.yaml, or from shellcheck on the two scripts.
• ./gradlew quickCheck passes.

Expected on CI. The longest fork of each job, in minutes, on the 2 Nov 12:18 run, with the shards packed on the
durations of the run before it (2 Nov 06:01). The packing is done the same way as the build does it, and each value
includes ~25 s of JVM start and exit:

Job	Now	With this change	Balanced
Broker Group 1	28.7	22.5	20.9
Broker Group 2	13.1	12.4	11.3
Broker Group 3	7.8	8.4	6.8
Broker Group 5	8.0	7.0	5.8
Client Api	14.2	10.7	9.4
Client Impl	15.8	13.6	11.7
Pulsar Metadata	17.8	8.4	8.0
Pulsar Client	4.2	2.6	2.4
Proxy	2.6	2.9	2.5

That is about 24 min less across the nine jobs. Broker Group 1, the CI's critical path, gets ~6 min shorter. Broker
Group 3 and Proxy happen to be well split today, and their fork order can change with any class that's added. On the
four earlier scheduled runs, the same packing cuts the nine longest forks' sum by 29–45 min.

Two limits:

• A class whose duration varies a lot between runs can't be balanced. KeySharedSubscriptionTest took 5 or 10 min,
  which kept Client Impl at ~19 min in two runs; [fix][test] Fix KeySharedSubscriptionTest hang caused by a leaked default message TTL #27296 fixes that swing.
• A class whose duration changes keeps its old weight until the next successful run records the new one. Together,
  [improve][test] Speed up TransactionEndToEndTest #27295, [fix][test] Fix KeySharedSubscriptionTest hang caused by a leaked default message TTL #27296 and [improve][test] Speed up the ack-timeout, negative-ack and DLQ tests #27298 cut Client Impl from 45 to 29 fork-min. The first run after them gets shards of 9.0 / 7.7 /
  7.5 / 6.3 min instead of 7.6 each, still well under today's 11.7.

This PR's first CI run has no recorded durations yet, so it runs test, as today. A re-run, or the next push,
restores the durations the first run saved, and should show the numbers above. The same happens once on master after
the merge.

Does this pull request potentially affect one of the following parts:

If the box was checked, please highlight the changes

• Dependencies (add or upgrade a dependency)
• The public API
• The schema
• The default values of configurations
• The threading model
• The binary protocol
• The REST endpoints
• The admin CLI options
• The metrics
• Anything that affects deployment