Skip to content

Commit 0dcea8d

Browse files
authored
feat(uplc-evaluator): use integer nanoseconds for timing measurements (#7552)
Replace floating-point milliseconds with integer nanoseconds to eliminate representation inconsistencies across platforms and precision loss in JSON serialization. Timing values now serialize as integers (cpu_time_ns) instead of floats (cpu_time_ms). Change TimingSample from data to newtype for zero-cost abstraction. Update criterion-measurement conversion to multiply by 1e9 and round to Word64. Adjust test assertions to validate nanosecond ranges (500ms = 500000000ns). Update SPEC.md with new field name, type, examples, and jq usage patterns. Closes IntersectMBO/plutus-private#2045
1 parent 7b89a1c commit 0dcea8d

File tree

4 files changed

+68
-68
lines changed

4 files changed

+68
-68
lines changed

plutus-benchmark/uplc-evaluator/Main.hs

Lines changed: 15 additions & 16 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,7 @@ import Data.Text qualified as T
2323
import Data.Text.IO qualified as TIO
2424
import Data.UUID (UUID)
2525
import Data.UUID qualified as UUID
26+
import Data.Word (Word64)
2627
import GHC.Generics (Generic)
2728
import Main.Utf8 (withUtf8)
2829
import Options.Applicative
@@ -75,16 +76,14 @@ configParser =
7576
<> help "Polling interval in milliseconds (default: 1000)"
7677
)
7778

78-
-- | Timing sample for a single evaluation run (variable data only)
79-
data TimingSample = TimingSample
80-
{ tsCpuTimeMs :: Double
81-
}
79+
-- | Timing sample for a single evaluation run
80+
newtype TimingSample = TimingSample {tsCpuTimeNs :: Word64}
8281
deriving stock (Generic, Show)
8382

8483
instance ToJSON TimingSample where
8584
toJSON TimingSample {..} =
8685
Aeson.object
87-
[ "cpu_time_ms" .= tsCpuTimeMs
86+
[ "cpu_time_ns" .= tsCpuTimeNs
8887
]
8988

9089
-- | Successful evaluation result with deterministic budget at top level
@@ -164,15 +163,15 @@ parseUplcProgram input =
164163
Right prog -> Right $ void prog
165164

166165
{-| Measure execution time of an IO action using criterion-measurement.
167-
Returns the result and execution time in milliseconds.
166+
Returns the result and execution time in nanoseconds.
168167
Uses evaluate+force to ensure the result is fully evaluated before measuring end time. -}
169-
measureExecution :: NFData a => IO a -> IO (a, Double)
168+
measureExecution :: NFData a => IO a -> IO (a, Word64)
170169
measureExecution ioAction = do
171170
startTime <- getTime
172171
result <- evaluate . force =<< ioAction
173172
endTime <- getTime
174-
let timeMs = (endTime - startTime) * 1000 -- Convert seconds to milliseconds
175-
return (result, timeMs)
173+
let timeNs = round ((endTime - startTime) * 1e9) -- Convert seconds to nanoseconds
174+
return (result, timeNs)
176175

177176
-- | Result of CEK evaluation with budget information
178177
data EvalBudget = EvalBudget
@@ -258,13 +257,13 @@ collectMeasurements term sampleCount = do
258257
let samples = map buildTimingSample timings
259258
return $ Right (budget, samples)
260259
where
261-
-- Measure a single execution and return wall-clock time in milliseconds
260+
-- Measure a single execution and return wall-clock time in nanoseconds
262261
measureSingleExecution
263262
:: UPLC.Term UPLC.NamedDeBruijn PLC.DefaultUni PLC.DefaultFun ()
264-
-> IO Double
263+
-> IO Word64
265264
measureSingleExecution t = do
266-
(_, timeMs) <- measureExecution $ return $! evalTerm t
267-
return timeMs
265+
(_, timeNs) <- measureExecution $ return $! evalTerm t
266+
return timeNs
268267

269268
-- Evaluate term (used for timing, result discarded)
270269
evalTerm
@@ -273,10 +272,10 @@ collectMeasurements term sampleCount = do
273272
evalTerm = evaluateWithBudget
274273

275274
-- Build a TimingSample from timing (only variable data)
276-
buildTimingSample :: Double -> TimingSample
277-
buildTimingSample cpuTimeMs =
275+
buildTimingSample :: Word64 -> TimingSample
276+
buildTimingSample cpuTimeNs =
278277
TimingSample
279-
{ tsCpuTimeMs = cpuTimeMs
278+
{ tsCpuTimeNs = cpuTimeNs
280279
}
281280

282281
-- | Process a single program file

plutus-benchmark/uplc-evaluator/SPEC.md

Lines changed: 38 additions & 38 deletions
Original file line numberDiff line numberDiff line change
@@ -671,7 +671,7 @@ Result files are JSON objects containing evaluation metrics from UPLC program ex
671671
"memory_bytes": <number>,
672672
"timing_samples": [
673673
{
674-
"cpu_time_ms": <number>
674+
"cpu_time_ns": <integer>
675675
},
676676
...
677677
]
@@ -746,15 +746,15 @@ An array of timing samples collected during program evaluation. Each program is
746746

747747
Each timing sample object in the `timing_samples` array contains:
748748

749-
#### `cpu_time_ms` (required)
749+
#### `cpu_time_ns` (required)
750750

751-
Wall-clock execution time in milliseconds. This measures the actual elapsed time for the CEK machine evaluation.
751+
Wall-clock execution time in nanoseconds. This measures the actual elapsed time for the CEK machine evaluation.
752752

753-
**Type**: Number (floating-point)
753+
**Type**: Integer
754754

755-
**Unit**: Milliseconds
755+
**Unit**: Nanoseconds
756756

757-
**Example**: `0.421`
757+
**Example**: `421000`
758758

759759
**Note**: This is wall-clock time, not CPU budget units. It reflects actual hardware performance and may vary between runs.
760760

@@ -768,25 +768,25 @@ Wall-clock execution time in milliseconds. This measures the actual elapsed time
768768
"memory_budget": 50000,
769769
"memory_bytes": 400000,
770770
"timing_samples": [
771-
{"cpu_time_ms": 0.421},
772-
{"cpu_time_ms": 0.398},
773-
{"cpu_time_ms": 0.415},
774-
{"cpu_time_ms": 0.402},
775-
{"cpu_time_ms": 0.419},
776-
{"cpu_time_ms": 0.408},
777-
{"cpu_time_ms": 0.411},
778-
{"cpu_time_ms": 0.425},
779-
{"cpu_time_ms": 0.403},
780-
{"cpu_time_ms": 0.417}
771+
{"cpu_time_ns": 421000},
772+
{"cpu_time_ns": 398000},
773+
{"cpu_time_ns": 415000},
774+
{"cpu_time_ns": 402000},
775+
{"cpu_time_ns": 419000},
776+
{"cpu_time_ns": 408000},
777+
{"cpu_time_ns": 411000},
778+
{"cpu_time_ns": 425000},
779+
{"cpu_time_ns": 403000},
780+
{"cpu_time_ns": 417000}
781781
]
782782
}
783783
```
784784

785785
**Observations from this example**:
786786
- 10 timing samples collected
787-
- `cpu_time_ms` shows variation between runs (0.398 to 0.425 ms)
787+
- `cpu_time_ns` shows variation between runs (398000 to 425000 ns)
788788
- Budget values (`cpu_budget`, `memory_budget`, `memory_bytes`) are deterministic and at top level
789-
- Clients should compute statistics: mean CPU time ≈ 0.412 ms, std dev ≈ 0.009 ms
789+
- Clients should compute statistics: mean CPU time ≈ 412000 ns (0.412 ms), std dev ≈ 9000 ns
790790

791791
### Example Result: Complex Program
792792

@@ -798,21 +798,21 @@ Wall-clock execution time in milliseconds. This measures the actual elapsed time
798798
"memory_budget": 10000000,
799799
"memory_bytes": 80000000,
800800
"timing_samples": [
801-
{"cpu_time_ms": 125.842},
802-
{"cpu_time_ms": 123.156},
803-
{"cpu_time_ms": 127.934},
804-
{"cpu_time_ms": 124.587},
805-
{"cpu_time_ms": 126.419},
806-
{"cpu_time_ms": 122.738},
807-
{"cpu_time_ms": 128.205},
808-
{"cpu_time_ms": 125.063},
809-
{"cpu_time_ms": 124.178},
810-
{"cpu_time_ms": 126.891},
811-
{"cpu_time_ms": 123.542},
812-
{"cpu_time_ms": 127.319},
813-
{"cpu_time_ms": 125.684},
814-
{"cpu_time_ms": 124.926},
815-
{"cpu_time_ms": 126.437}
801+
{"cpu_time_ns": 125842000},
802+
{"cpu_time_ns": 123156000},
803+
{"cpu_time_ns": 127934000},
804+
{"cpu_time_ns": 124587000},
805+
{"cpu_time_ns": 126419000},
806+
{"cpu_time_ns": 122738000},
807+
{"cpu_time_ns": 128205000},
808+
{"cpu_time_ns": 125063000},
809+
{"cpu_time_ns": 124178000},
810+
{"cpu_time_ns": 126891000},
811+
{"cpu_time_ns": 123542000},
812+
{"cpu_time_ns": 127319000},
813+
{"cpu_time_ns": 125684000},
814+
{"cpu_time_ns": 124926000},
815+
{"cpu_time_ns": 126437000}
816816
]
817817
}
818818
```
@@ -850,7 +850,7 @@ Std deviation: 0.009 ms
850850
- Results are written to `/benchmarking/output/{job_id}.result.json` when evaluation completes successfully
851851
- Result files remain available until cleanup (see retention policy)
852852
- Budget values (`cpu_budget`, `memory_budget`, `memory_bytes`) are deterministic for a given program and cost model
853-
- Wall-clock times (`cpu_time_ms`) may vary between runs due to system load
853+
- Wall-clock times (`cpu_time_ns`) may vary between runs due to system load
854854
- Multiple timing samples enable statistical confidence in measurements
855855
- Budget consumption is independent of hardware performance (cost model is abstract)
856856
- Clients should parse JSON and extract timing_samples array for statistical analysis
@@ -1501,10 +1501,10 @@ Parse the result JSON and extract metrics:
15011501

15021502
```bash
15031503
# Parse result JSON and extract timing samples
1504-
jq '.timing_samples[] | {cpu_time_ms}' ./results/${JOB_ID}.result.json
1504+
jq '.timing_samples[] | {cpu_time_ns}' ./results/${JOB_ID}.result.json
15051505

1506-
# Compute statistics (mean CPU time)
1507-
jq '[.timing_samples[].cpu_time_ms] | add / length' ./results/${JOB_ID}.result.json
1506+
# Compute statistics (mean CPU time in nanoseconds)
1507+
jq '[.timing_samples[].cpu_time_ns] | add / length' ./results/${JOB_ID}.result.json
15081508

15091509
# Check budget consumption (deterministic values at top level)
15101510
jq '{cpu_budget, memory_budget, memory_bytes}' ./results/${JOB_ID}.result.json
@@ -1679,7 +1679,7 @@ while [ $TOTAL_WAIT -lt $MAX_TOTAL_WAIT ]; do
16791679
echo "=== Result Summary ==="
16801680
echo "Program ID: $JOB_ID"
16811681
echo "Sample count: $(jq '.timing_samples | length' ./results/${JOB_ID}.result.json)"
1682-
echo "Mean CPU time: $(jq '[.timing_samples[].cpu_time_ms] | add / length' ./results/${JOB_ID}.result.json) ms"
1682+
echo "Mean CPU time: $(jq '[.timing_samples[].cpu_time_ns] | add / length / 1000000' ./results/${JOB_ID}.result.json) ms"
16831683
echo "CPU budget: $(jq '.cpu_budget' ./results/${JOB_ID}.result.json) ExCPU"
16841684
echo "Memory budget: $(jq '.memory_budget' ./results/${JOB_ID}.result.json) ExMemory"
16851685
echo ""

plutus-benchmark/uplc-evaluator/test/Spec.hs

Lines changed: 11 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -90,13 +90,13 @@ main = defaultMain $ testGroup "uplc-evaluator integration tests" do
9090
("timing_samples should have 10-20 entries, got " ++ show sampleCount)
9191
(sampleCount >= 10 && sampleCount <= 20)
9292

93-
-- Verify each timing sample has positive cpu_time_ms
93+
-- Verify each timing sample has positive cpu_time_ns
9494
mapM_
9595
( \s -> do
96-
-- Check that cpu_time_ms is in reasonable range
96+
-- Check that cpu_time_ns is in reasonable range
9797
assertBool
98-
("cpu_time_ms should be > 0, got " ++ show (tsCpuTimeMs s))
99-
(tsCpuTimeMs s > 0)
98+
("cpu_time_ns should be > 0, got " ++ show (tsCpuTimeNs s))
99+
(tsCpuTimeNs s > 0)
100100
)
101101
(erTimingSamples result)
102102

@@ -501,14 +501,14 @@ main = defaultMain $ testGroup "uplc-evaluator integration tests" do
501501
("memory_bytes should be >= 0 and <= 10485760, got " ++ show memBytes)
502502
(memBytes >= 0 && memBytes <= 10485760)
503503

504-
-- Verify each timing sample has cpu_time_ms in expected range
504+
-- Verify each timing sample has cpu_time_ns in expected range
505505
-- Simple programs can evaluate in microseconds
506506
mapM_
507507
( \s -> do
508-
let cpuTime = tsCpuTimeMs s
508+
let cpuTime = tsCpuTimeNs s
509509
assertBool
510-
("cpu_time_ms should be >= 0 and <= 500.0, got " ++ show cpuTime)
511-
(cpuTime >= 0 && cpuTime <= 500.0)
510+
("cpu_time_ns should be >= 0 and <= 500000000, got " ++ show cpuTime)
511+
(cpuTime >= 0 && cpuTime <= 500000000)
512512
)
513513
samples
514514
]
@@ -546,13 +546,13 @@ main = defaultMain $ testGroup "uplc-evaluator integration tests" do
546546
("memory_bytes should be > 0, got " ++ show (erMemoryBytes result))
547547
(erMemoryBytes result > 0)
548548

549-
-- cpu_time_ms values may vary (timing is non-deterministic)
549+
-- cpu_time_ns values may vary (timing is non-deterministic)
550550
-- We just verify they exist and are positive
551-
let cpuTimes = map tsCpuTimeMs samples
551+
let cpuTimes = map tsCpuTimeNs samples
552552
mapM_
553553
( \t ->
554554
assertBool
555-
("cpu_time_ms should be > 0, got " ++ show t)
555+
("cpu_time_ns should be > 0, got " ++ show t)
556556
(t > 0)
557557
)
558558
cpuTimes

plutus-benchmark/uplc-evaluator/test/TestHelpers.hs

Lines changed: 4 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -36,22 +36,23 @@ import Data.Text (Text)
3636
import Data.Text qualified as T
3737
import Data.UUID (UUID)
3838
import Data.UUID qualified as UUID
39+
import Data.Word (Word64)
3940
import GHC.Generics (Generic)
4041
import Harness (ServiceHandle (..))
4142
import System.Directory (doesFileExist)
4243
import System.FilePath ((</>))
4344
import Test.Tasty.HUnit (assertFailure)
4445

4546
-- | Timing sample for a single evaluation run (variable data only)
46-
data TimingSample = TimingSample
47-
{ tsCpuTimeMs :: Double
47+
newtype TimingSample = TimingSample
48+
{ tsCpuTimeNs :: Word64
4849
}
4950
deriving stock (Generic, Show, Eq)
5051

5152
instance FromJSON TimingSample where
5253
parseJSON = Aeson.withObject "TimingSample" \v ->
5354
TimingSample
54-
<$> v .: "cpu_time_ms"
55+
<$> v .: "cpu_time_ns"
5556

5657
-- | Successful evaluation result with deterministic budget at top level
5758
data EvalResult = EvalResult

0 commit comments

Comments
 (0)