Skip to content

Commit efc9927

Browse files
committed
Show CLI integration test timings in Actions
Signed-off-by: Igor Konnov <igor@konnov.phd>
1 parent 9c23931 commit efc9927

7 files changed

Lines changed: 793 additions & 1 deletion

File tree

.github/workflows/main.yml

Lines changed: 24 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -152,10 +152,34 @@ jobs:
152152
- uses: sbt/setup-sbt@v1
153153
- name: Set APALACHE_HOME env
154154
run: echo "APALACHE_HOME=$GITHUB_WORKSPACE" >> $GITHUB_ENV
155+
- name: Test CLI integration timing report
156+
run: python3 -m unittest discover -s test -p 'test_cli_integration_timing_report.py'
155157
- name: Run Scala CLI integration tests
156158
run: make scala-integration
157159
env:
158160
APALACHE_CLI_TEST_CONFIGS: ${{ matrix.test-configurations }}
161+
APALACHE_CLI_TEST_TIMING: true
162+
APALACHE_CLI_TEST_TIMING_DIR: ${{ runner.temp }}/apalache-cli-integration-timings
163+
- name: Add CLI integration timings to the job summary
164+
if: always()
165+
shell: bash
166+
run: |
167+
python3 script/cli_integration_timing_report.py \
168+
--input "$RUNNER_TEMP/apalache-cli-integration-timings" \
169+
--markdown "$RUNNER_TEMP/cli-integration-timing-summary.md" \
170+
--csv "$RUNNER_TEMP/cli-integration-timings.csv" \
171+
--label "${{ matrix.operating-system }} / ${{ matrix.test-configurations }}"
172+
cat "$RUNNER_TEMP/cli-integration-timing-summary.md" >> "$GITHUB_STEP_SUMMARY"
173+
- name: Upload CLI integration timing data
174+
if: always()
175+
uses: actions/upload-artifact@v7
176+
with:
177+
name: cli-integration-timings-${{ matrix.operating-system }}-${{ matrix.test-configurations }}
178+
path: |
179+
${{ runner.temp }}/apalache-cli-integration-timings/*.jsonl
180+
${{ runner.temp }}/cli-integration-timings.csv
181+
if-no-files-found: warn
182+
retention-days: 14
159183
- name: Cleanup before cache
160184
# See https://www.scala-sbt.org/1.x/docs/GitHub-Actions-with-sbt.html#Caching
161185
shell: bash

build.sbt

Lines changed: 12 additions & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -405,7 +405,18 @@ lazy val tool = (project in file("mod-tool"))
405405
CliIntegration / resourceDirectory := (Test / resourceDirectory).value,
406406
CliIntegration / fork := true,
407407
CliIntegration / parallelExecution := true,
408-
CliIntegration / testOptions += Tests.Argument(TestFrameworks.ScalaTest, "-oCDEH"),
408+
CliIntegration / logBuffered := false,
409+
CliIntegration / testOptions += Tests.Argument(
410+
TestFrameworks.ScalaTest,
411+
"-C",
412+
"org.apalachemc.integration.framework.IntegrationTimingReporter",
413+
// Report a test every 30 seconds while it is still running. This makes
414+
// unexpectedly slow tests visible in the live Actions log as well as
415+
// in the post-run timing summary.
416+
"-W",
417+
"30",
418+
"30",
419+
),
409420
CliIntegration / javaOptions ++= {
410421
val javaFeature = java.lang.Runtime.version().feature()
411422
val compatibilityOptions =
Lines changed: 95 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,95 @@
1+
package org.apalachemc.integration
2+
3+
import java.nio.file.Files
4+
5+
import org.apalachemc.integration.framework.{IntegrationTestBase, IntegrationTimingReporter}
6+
import org.scalatest.events.{Ordinal, TestStarting, TestSucceeded}
7+
8+
class IntegrationTimingReporterTest extends IntegrationTestBase {
9+
test("the timing reporter flushes versioned start and completion records") {
10+
val output = workspace.root.resolve("reporter-test.jsonl")
11+
val reporter = new IntegrationTimingReporter(output, "test-configuration")
12+
val ordinal = new Ordinal(1)
13+
14+
reporter(
15+
TestStarting(
16+
ordinal,
17+
"Example suite",
18+
"example-suite-id",
19+
Some("example.Suite"),
20+
"does useful work",
21+
"does useful work",
22+
timeStamp = 1000L,
23+
))
24+
25+
val start = ujson.read(Files.readString(output)).obj
26+
assert(start("schemaVersion").num == 1)
27+
assert(start("event").str == "started")
28+
assert(start("configuration").str == "test-configuration")
29+
30+
reporter(
31+
TestSucceeded(
32+
ordinal.next,
33+
"Example suite",
34+
"example-suite-id",
35+
Some("example.Suite"),
36+
"does useful work",
37+
"does useful work",
38+
IndexedSeq.empty,
39+
duration = Some(250L),
40+
timeStamp = 1250L,
41+
))
42+
reporter.dispose()
43+
44+
val records = Files.readAllLines(output)
45+
assert(records.size() == 2)
46+
val completion = ujson.read(records.get(1)).obj
47+
assert(completion("event").str == "finished")
48+
assert(completion("status").str == "succeeded")
49+
assert(completion("durationMillis").num == 250)
50+
}
51+
52+
test("the timing reporter separates concurrent configuration workers") {
53+
val outputDirectory = workspace.root.resolve("timings")
54+
val reporter = new IntegrationTimingReporter(outputDirectory)
55+
val configurations = Seq("oopsla19-z3", "oopsla19-cvc5", "arrays-z3")
56+
57+
configurations.zipWithIndex.foreach { case (configuration, index) =>
58+
val ordinal = new Ordinal(index + 1)
59+
val suiteName = s"Example suite [$configuration]"
60+
reporter(
61+
TestStarting(
62+
ordinal,
63+
suiteName,
64+
"example-suite-id",
65+
Some("example.Suite"),
66+
"does useful work",
67+
"does useful work",
68+
timeStamp = 1000L,
69+
))
70+
reporter(
71+
TestSucceeded(
72+
ordinal.next,
73+
suiteName,
74+
"example-suite-id",
75+
Some("example.Suite"),
76+
"does useful work",
77+
"does useful work",
78+
IndexedSeq.empty,
79+
duration = Some(250L),
80+
timeStamp = 1250L,
81+
))
82+
}
83+
reporter.dispose()
84+
85+
configurations.foreach { configuration =>
86+
val records = Files.readAllLines(outputDirectory.resolve(s"$configuration.jsonl"))
87+
assert(records.size() == 2)
88+
records.forEach { record =>
89+
val json = ujson.read(record).obj
90+
assert(json("configuration").str == configuration)
91+
assert(json("suiteName").str == "Example suite")
92+
}
93+
}
94+
}
95+
}

mod-tool/src/test/scala/org/apalachemc/integration/README.md

Lines changed: 15 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -86,3 +86,18 @@ sbt 'tool/CliIntegration/testOnly org.apalachemc.integration.ParseCommandTest --
8686
expanded across the selected workers, and the suite itself skips workers it does not support.
8787

8888
Set `APALACHE_CLI_TEST_TIMING=true` to print the active configuration and elapsed time of each Tool invocation.
89+
90+
ScalaTest also writes per-test start and completion events to configuration-specific JSONL files. By default they
91+
are under `target/cli-integration-timings`; set `APALACHE_CLI_TEST_TIMING_DIR` to choose another
92+
directory. Generate the same Markdown summary and CSV diagnostics used in GitHub Actions with:
93+
94+
```sh
95+
python3 script/cli_integration_timing_report.py \
96+
--input target/cli-integration-timings \
97+
--markdown /tmp/cli-integration-timings.md \
98+
--csv /tmp/cli-integration-timings.csv \
99+
--label local
100+
```
101+
102+
The Actions job summary shows quartiles, the median, Tukey outliers, and a Mermaid chart of the ten slowest tests
103+
for each configuration. Timing data is informational and does not introduce a performance gate.
Lines changed: 176 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,176 @@
1+
package org.apalachemc.integration.framework
2+
3+
import java.io.{BufferedWriter, IOException}
4+
import java.nio.charset.StandardCharsets
5+
import java.nio.file.{Files, Path, Paths, StandardOpenOption}
6+
7+
import scala.collection.mutable
8+
9+
import org.scalatest.ResourcefulReporter
10+
import org.scalatest.events.{
11+
Event,
12+
RunAborted,
13+
RunCompleted,
14+
RunStopped,
15+
TestCanceled,
16+
TestFailed,
17+
TestPending,
18+
TestStarting,
19+
TestSucceeded,
20+
}
21+
22+
/** Writes configuration-aware ScalaTest timing events as JSON Lines.
23+
*
24+
* A start record is flushed before each test runs. If the worker is killed, the
25+
* report generator can therefore identify the test that never produced a
26+
* matching completion record.
27+
*/
28+
final class IntegrationTimingReporter private[integration] (
29+
outputDirectory: Path,
30+
forcedOutputPath: Option[Path],
31+
forcedConfiguration: Option[String])
32+
extends ResourcefulReporter {
33+
import IntegrationTimingReporter._
34+
35+
private val startedAt = mutable.Map.empty[TestId, Long]
36+
private val writers = mutable.Map.empty[String, BufferedWriter]
37+
private var closed = false
38+
39+
/** Constructor used by focused reporter tests. */
40+
private[integration] def this(outputPath: Path, configuration: String) =
41+
this(outputPath.getParent, Some(outputPath), Some(configuration))
42+
43+
/** Constructor used to test configuration routing without changing process environment. */
44+
private[integration] def this(outputDirectory: Path) =
45+
this(outputDirectory, None, None)
46+
47+
/** Public no-argument constructor required by ScalaTest's `-C` option. */
48+
def this() = this(
49+
IntegrationTimingReporter.defaultOutputDirectory(),
50+
None,
51+
None,
52+
)
53+
54+
override def apply(event: Event): Unit = synchronized {
55+
if (!closed) {
56+
event match {
57+
case event: TestStarting =>
58+
val (configuration, suiteName) = configurationAndSuiteName(event.suiteName)
59+
val id = TestId(configuration, event.suiteId, event.testName)
60+
startedAt.put(id, event.timeStamp)
61+
write(
62+
configuration,
63+
ujson.Obj(
64+
"schemaVersion" -> SchemaVersion,
65+
"event" -> "started",
66+
"configuration" -> configuration,
67+
"suiteId" -> event.suiteId,
68+
"suiteName" -> suiteName,
69+
"testName" -> event.testName,
70+
"timestampEpochMillis" -> ujson.Num(event.timeStamp.toDouble),
71+
))
72+
73+
case event: TestSucceeded =>
74+
finish(event.suiteId, event.suiteName, event.testName, "succeeded", event.duration, event.timeStamp)
75+
case event: TestFailed =>
76+
finish(event.suiteId, event.suiteName, event.testName, "failed", event.duration, event.timeStamp)
77+
case event: TestCanceled =>
78+
finish(event.suiteId, event.suiteName, event.testName, "canceled", event.duration, event.timeStamp)
79+
case event: TestPending =>
80+
finish(event.suiteId, event.suiteName, event.testName, "pending", event.duration, event.timeStamp)
81+
82+
case _: RunCompleted | _: RunAborted | _: RunStopped => dispose()
83+
case _ => ()
84+
}
85+
}
86+
}
87+
88+
override def dispose(): Unit = synchronized {
89+
if (!closed) {
90+
closed = true
91+
writers.values.foreach(_.close())
92+
writers.clear()
93+
}
94+
}
95+
96+
private def finish(
97+
suiteId: String,
98+
suiteName: String,
99+
testName: String,
100+
status: String,
101+
reportedDuration: Option[Long],
102+
timestamp: Long): Unit = {
103+
val (configuration, unqualifiedSuiteName) = configurationAndSuiteName(suiteName)
104+
val id = TestId(configuration, suiteId, testName)
105+
val measuredDuration = startedAt.remove(id).map(start => math.max(0L, timestamp - start))
106+
val duration = reportedDuration.orElse(measuredDuration).getOrElse(0L)
107+
write(
108+
configuration,
109+
ujson.Obj(
110+
"schemaVersion" -> SchemaVersion,
111+
"event" -> "finished",
112+
"configuration" -> configuration,
113+
"suiteId" -> suiteId,
114+
"suiteName" -> unqualifiedSuiteName,
115+
"testName" -> testName,
116+
"status" -> status,
117+
"timestampEpochMillis" -> ujson.Num(timestamp.toDouble),
118+
"durationMillis" -> ujson.Num(duration.toDouble),
119+
))
120+
}
121+
122+
private def write(configuration: String, record: ujson.Obj): Unit = {
123+
val outputPath = forcedOutputPath.getOrElse(outputDirectory.resolve(s"$configuration.jsonl"))
124+
val writer = writers.getOrElseUpdate(configuration, open(outputPath))
125+
writer.write(record.render())
126+
writer.newLine()
127+
writer.flush()
128+
}
129+
130+
private def configurationAndSuiteName(suiteName: String): (String, String) = {
131+
forcedConfiguration
132+
.map(_ -> suiteName)
133+
.getOrElse {
134+
ConfigurationIds
135+
.collectFirst {
136+
case configuration if suiteName.endsWith(s" [$configuration]") =>
137+
configuration -> suiteName.stripSuffix(s" [$configuration]")
138+
}
139+
.getOrElse("general" -> suiteName)
140+
}
141+
}
142+
}
143+
144+
private[integration] object IntegrationTimingReporter {
145+
val SchemaVersion = 1
146+
val TimingDirectoryProperty = "apalache.cli.test.timing-dir"
147+
148+
private case class TestId(configuration: String, suiteId: String, testName: String)
149+
150+
private val ConfigurationIds = IntegrationTestConfiguration.values.map(_.id)
151+
152+
private[integration] def defaultOutputDirectory(): Path = {
153+
sys.env
154+
.get("APALACHE_CLI_TEST_TIMING_DIR")
155+
.filter(_.nonEmpty)
156+
.orElse(Option(System.getProperty(TimingDirectoryProperty)).filter(_.nonEmpty))
157+
.map(Paths.get(_))
158+
.getOrElse(Paths.get("target", "cli-integration-timings"))
159+
}
160+
161+
private def open(outputPath: Path): BufferedWriter = {
162+
Option(outputPath.getParent).foreach(Files.createDirectories(_))
163+
try {
164+
Files.newBufferedWriter(
165+
outputPath,
166+
StandardCharsets.UTF_8,
167+
StandardOpenOption.CREATE,
168+
StandardOpenOption.TRUNCATE_EXISTING,
169+
StandardOpenOption.WRITE,
170+
)
171+
} catch {
172+
case exception: IOException =>
173+
throw new IllegalStateException(s"Could not open integration-test timing report $outputPath", exception)
174+
}
175+
}
176+
}

0 commit comments

Comments
 (0)