chore: Report prover metrics

[spalladino]

Reports a new histogram metric with the time that passes between a block being submitted and its proof. Uses the timestamp from the L2 block header global variables as block submission time, and the L1 block time for the proof submission time.

Depends on #8193

Fixes #7675

[spalladino]

@alexghr I had to make this change or the metrics profile from the docker-compose template (thanks for setting that up btw!) complained with:

otel-collector-1  | 2024-08-22T21:58:16.616Z	error	prometheusexporter@v0.107.0/log.go:23	error gathering metrics: collected metric target_info label:{name:"aztec_network_name" value:"local"} label:{name:"instance" value:"cc74bc34-eda7-48a7-99e1-c7fc76425af9"} label:{name:"job" value:"unknown_service:/home/santiago/.nvm/versions/node/v18.19.0/bin/node"} label:{name:"os_type" value:"linux"} label:{name:"os_version" value:"6.8.0-36-generic"} label:{name:"process_command" value:"/home/santiago/Projects/aztec3-packages-5/yarn-project/aztec/dest/bin/index.js"} label:{name:"process_command_args" value:"[\"/home/santiago/.nvm/versions/node/v18.19.0/bin/node\",\"/home/santiago/Projects/aztec3-packages-5/yarn-project/aztec/dest/bin/index.js\",\"start\",\"--node\",\"--archiver\",\"--sequencer\",\"--pxe\"]"} label:{name:"process_executable_name" value:"/home/santiago/.nvm/versions/node/v18.19.0/bin/node"} label:{name:"process_executable_path" value:"/home/santiago/.nvm/versions/node/v18.19.0/bin/node"} label:{name:"process_owner" value:"santiago"} label:{name:"process_pid" value:"98021"} label:{name:"process_runtime_description" value:"Node.js"} label:{name:"process_runtime_name" value:"nodejs"} label:{name:"process_runtime_version" value:"18.19.0"} label:{name:"service_instance_id" value:"cc74bc34-eda7-48a7-99e1-c7fc76425af9"} gauge:{value:1} has help "Target information" but should have "Target metadata"
otel-collector-1  | 	{"kind": "exporter", "data_type": "metrics", "name": "prometheus"}
otel-collector-1  | github.com/open-telemetry/opentelemetry-collector-contrib/exporter/prometheusexporter.(*promLogger).Println
otel-collector-1  | 	github.com/open-telemetry/opentelemetry-collector-contrib/exporter/prometheusexporter@v0.107.0/log.go:23
otel-collector-1  | github.com/prometheus/client_golang/prometheus/promhttp.HandlerForTransactional.func1
otel-collector-1  | 	github.com/prometheus/client_golang@v1.19.1/prometheus/promhttp/http.go:144
otel-collector-1  | net/http.HandlerFunc.ServeHTTP
otel-collector-1  | 	net/http/server.go:2171
otel-collector-1  | net/http.(*ServeMux).ServeHTTP
otel-collector-1  | 	net/http/server.go:2688
otel-collector-1  | go.opentelemetry.io/collector/config/confighttp.(*decompressor).ServeHTTP
otel-collector-1  | 	go.opentelemetry.io/collector/config/confighttp@v0.107.0/compression.go:172
otel-collector-1  | go.opentelemetry.io/collector/config/confighttp.(*ServerConfig).ToServer.maxRequestBodySizeInterceptor.func2
otel-collector-1  | 	go.opentelemetry.io/collector/config/confighttp@v0.107.0/confighttp.go:543
otel-collector-1  | net/http.HandlerFunc.ServeHTTP
otel-collector-1  | 	net/http/server.go:2171
otel-collector-1  | go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.(*middleware).serveHTTP
otel-collector-1  | 	go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.53.0/handler.go:218
otel-collector-1  | go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp.NewMiddleware.func1.1
otel-collector-1  | 	go.opentelemetry.io/contrib/instrumentation/net/http/otelhttp@v0.53.0/handler.go:74
otel-collector-1  | net/http.HandlerFunc.ServeHTTP
otel-collector-1  | 	net/http/server.go:2171
otel-collector-1  | go.opentelemetry.io/collector/config/confighttp.(*clientInfoHandler).ServeHTTP
otel-collector-1  | 	go.opentelemetry.io/collector/config/confighttp@v0.107.0/clientinfohandler.go:26
otel-collector-1  | net/http.serverHandler.ServeHTTP
otel-collector-1  | 	net/http/server.go:3142
otel-collector-1  | net/http.(*conn).serve
otel-collector-1  | 	net/http/server.go:2044

[AztecBot]

Benchmark results

Metrics with a significant change:

• avm_simulation_time_ms (Token:transfer_public): 20.2 (-57%)
• protocol_circuit_witness_generation_time_in_ms (private-kernel-tail): 197 (+44%)

Detailed results

All benchmarks are run on txs on the Benchmarking contract on the repository. Each tx consists of a batch call to create_note and increment_balance, which guarantees that each tx has a private call, a nested private call, a public call, and a nested public call, as well as an emitted private note, an unencrypted log, and public storage read and write.

This benchmark source data is available in JSON format on S3 here.

Proof generation

Each column represents the number of threads used in proof generation.

Metric	1 threads	4 threads	16 threads	32 threads	64 threads
proof_construction_time_sha256_ms	5,746	1,560	705 (-1%)	772 (+5%)	771
proof_construction_time_sha256_30_ms	11,480	3,081	1,385 (+1%)	1,434 (+1%)	1,458
proof_construction_time_sha256_100_ms	43,934	11,745	5,405	5,396	5,729
proof_construction_time_poseidon_hash_ms	78.0	34.0	34.0	58.0 (+2%)	87.0 (-2%)
proof_construction_time_poseidon_hash_30_ms	1,528	421	204	225 (-2%)	267 (-1%)
proof_construction_time_poseidon_hash_100_ms	5,632	1,510	671	723 (-2%)	745 (-1%)

L2 block published to L1

Each column represents the number of txs on an L2 block published to L1.

Metric	4 txs	8 txs	16 txs
l1_rollup_calldata_size_in_bytes	4,356	7,876	14,884
l1_rollup_calldata_gas	50,268	92,976	177,988
l1_rollup_execution_gas	842,928	1,576,532	3,361,600
l2_block_processing_time_in_ms	246 (+1%)	462 (+5%)	794 (-3%)
l2_block_building_time_in_ms	11,372 (-1%)	22,274	44,333 (-1%)
l2_block_rollup_simulation_time_in_ms	11,371 (-1%)	22,274	44,332 (-1%)
l2_block_public_tx_process_time_in_ms	9,642 (-1%)	20,445	42,504 (-1%)

L2 chain processing

Each column represents the number of blocks on the L2 chain where each block has 8 txs.

Metric	3 blocks	5 blocks
node_history_sync_time_in_ms	3,052 (+3%)	4,033 (+7%)
node_database_size_in_bytes	12,619,856	16,699,472
pxe_database_size_in_bytes	16,254	26,813

Circuits stats

Stats on running time and I/O sizes collected for every kernel circuit run across all benchmarks.

Circuit	simulation_time_in_ms	witness_generation_time_in_ms	input_size_in_bytes	output_size_in_bytes	proving_time_in_ms
private-kernel-init	92.4 (-7%)	415 (+3%)	21,735	44,860	N/A
private-kernel-inner	184 (+5%)	706 (-1%)	72,544	45,007	N/A
private-kernel-reset-tiny	309 (-2%)	716 (-1%)	65,593	44,846	N/A
private-kernel-tail	172 (+3%)	⚠️ 197 (+44%)	50,644	52,257	N/A
base-parity	5.61 (-1%)	N/A	160	96.0	N/A
root-parity	35.5	N/A	73,948	96.0	N/A
base-rollup	3,442 (-1%)	N/A	189,136	664	N/A
block-root-rollup	41.5	N/A	58,205	2,448	N/A
public-kernel-setup	86.2 (+1%)	N/A	105,085	71,222	N/A
public-kernel-app-logic	97.1	N/A	104,911	71,222	N/A
public-kernel-tail	863	N/A	390,582	16,414	N/A
private-kernel-reset-small	316 (+1%)	N/A	66,341	45,629	N/A
private-kernel-tail-to-public	668 (+1%)	616	455,400	1,825	N/A
public-kernel-teardown	85.0 (+1%)	N/A	105,349	71,222	N/A
merge-rollup	20.3	N/A	38,174	664	N/A
undefined	N/A	N/A	N/A	N/A	79,236 (+1%)

Stats on running time collected for app circuits

Function	input_size_in_bytes	output_size_in_bytes	witness_generation_time_in_ms
ContractClassRegisterer:register	1,344	11,731	345 (-1%)
ContractInstanceDeployer:deploy	1,408	11,731	18.3
MultiCallEntrypoint:entrypoint	1,920	11,731	408
FeeJuice:deploy	1,376	11,731	394 (+1%)
SchnorrAccount:constructor	1,312	11,731	73.7
SchnorrAccount:entrypoint	2,304	11,731	395
Token:privately_mint_private_note	1,280	11,731	105 (-2%)
FPC:fee_entrypoint_public	1,344	11,731	25.4 (-5%)
Token:transfer	1,312	11,731	225
Benchmarking:create_note	1,344	11,731	87.7 (+2%)
SchnorrAccount:verify_private_authwit	1,280	11,731	27.7 (-1%)
Token:unshield	1,376	11,731	522 (-2%)
FPC:fee_entrypoint_private	1,376	11,731	706 (-2%)

AVM Simulation

Time to simulate various public functions in the AVM.

Function	time_ms	bytecode_size_in_bytes
FeeJuice:_increase_public_balance	61.4 (+2%)	7,101
FeeJuice:set_portal	12.2 (+10%)	2,128
Token:constructor	82.6 (-1%)	25,285
FPC:constructor	53.7 (-2%)	17,853
FeeJuice:mint_public	39.3 (-1%)	5,415
Token:mint_public	70.4	10,101
Token:assert_minter_and_mint	40.9 (-1%)	6,844
AuthRegistry:set_authorized	38.2 (-19%)	3,969
FPC:prepare_fee	240	6,747
Token:transfer_public	⚠️ 20.2 (-57%)	38,126
FPC:pay_refund	53.3 (-5%)	9,398
Benchmarking:increment_balance	1,196	6,179
Token:_increase_public_balance	40.3 (-9%)	7,705
FPC:pay_refund_with_shielded_rebate	62.5 (-4%)	9,881

Public DB Access

Time to access various public DBs.

Function	time_ms
get-nullifier-index	0.161 (+2%)

Tree insertion stats

The duration to insert a fixed batch of leaves into each tree type.

Metric	1 leaves	16 leaves	64 leaves	128 leaves	256 leaves	512 leaves	1024 leaves
batch_insert_into_append_only_tree_16_depth_ms	2.18 (-2%)	3.95 (+1%)	N/A	N/A	N/A	N/A	N/A
batch_insert_into_append_only_tree_16_depth_hash_count	16.8	31.7	N/A	N/A	N/A	N/A	N/A
batch_insert_into_append_only_tree_16_depth_hash_ms	0.114 (-1%)	0.112 (+1%)	N/A	N/A	N/A	N/A	N/A
batch_insert_into_append_only_tree_32_depth_ms	N/A	N/A	11.4 (-2%)	17.7	30.6 (-3%)	60.4 (+1%)	111 (-4%)
batch_insert_into_append_only_tree_32_depth_hash_count	N/A	N/A	95.9	159	287	543	1,055
batch_insert_into_append_only_tree_32_depth_hash_ms	N/A	N/A	0.109 (-2%)	0.103	0.0997 (-2%)	0.104 (+1%)	0.0998 (-3%)
batch_insert_into_indexed_tree_20_depth_ms	N/A	N/A	14.4 (-1%)	25.7 (+1%)	43.8 (-1%)	83.4	159 (-3%)
batch_insert_into_indexed_tree_20_depth_hash_count	N/A	N/A	109	207	355	691	1,363
batch_insert_into_indexed_tree_20_depth_hash_ms	N/A	N/A	0.110 (-1%)	0.104	0.106 (-1%)	0.103	0.0993 (-4%)
batch_insert_into_indexed_tree_40_depth_ms	N/A	N/A	16.7	N/A	N/A	N/A	N/A
batch_insert_into_indexed_tree_40_depth_hash_count	N/A	N/A	132	N/A	N/A	N/A	N/A
batch_insert_into_indexed_tree_40_depth_hash_ms	N/A	N/A	0.107	N/A	N/A	N/A	N/A

Miscellaneous

Transaction sizes based on how many contract classes are registered in the tx.

Metric	0 registered classes	1 registered classes
tx_size_in_bytes	64,779	668,997

Transaction size based on fee payment method

| Metric | |
| - | |

[alexghr]

Just a heads up that this will cause a warning to be logged if log.delay is not an integer. I usually round up if we don't need sub-ms precision:

Suggested change

	this.proofsSubmitted.record(Number(log.delay), {
	this.proofsSubmitted.record(Math.ceil(Number(log.delay)), {

[alexghr]

Each prover+block combination would get its own histogram. Might be better to turn this into a gauge since a prover+block pair would only have a single data point?

[alexghr]

Alternatively we could have different instruments:

• a histogram to track proof delay (for all prover_id,block_number pairs)
• a gauge similar to target_info for (prover_id,block_number,delay_ms)

[spalladino]

Sample widget using the counter:

Code for the widget:

{
  "type": "timeseries",
  "title": "Proven blocks by prover",
  "gridPos": {
    "x": 0,
    "y": 52,
    "w": 12,
    "h": 8
  },
  "datasource": {
    "uid": "aztec-node-metrics",
    "type": "prometheus"
  },
  "id": 60,
  "targets": [
    {
      "refId": "A",
      "expr": "aztec_archiver_rollup_proof_count",
      "range": true,
      "instant": false,
      "datasource": {
        "type": "prometheus",
        "uid": "aztec-node-metrics"
      },
      "editorMode": "builder",
      "legendFormat": "{{aztec_rollup_prover_id}}",
      "useBackend": false,
      "disableTextWrap": false,
      "fullMetaSearch": false,
      "includeNullMetadata": true
    }
  ],
  "options": {
    "tooltip": {
      "mode": "single",
      "sort": "none"
    },
    "legend": {
      "showLegend": true,
      "displayMode": "table",
      "placement": "bottom",
      "calcs": [
        "last"
      ]
    }
  },
  "fieldConfig": {
    "defaults": {
      "custom": {
        "drawStyle": "line",
        "lineInterpolation": "linear",
        "barAlignment": 0,
        "lineWidth": 1,
        "fillOpacity": 0,
        "gradientMode": "none",
        "spanNulls": false,
        "insertNulls": false,
        "showPoints": "auto",
        "pointSize": 5,
        "stacking": {
          "mode": "none",
          "group": "A"
        },
        "axisPlacement": "auto",
        "axisLabel": "",
        "axisColorMode": "text",
        "axisBorderShow": false,
        "scaleDistribution": {
          "type": "linear"
        },
        "axisCenteredZero": false,
        "hideFrom": {
          "tooltip": false,
          "viz": false,
          "legend": false
        },
        "thresholdsStyle": {
          "mode": "off"
        }
      },
      "color": {
        "mode": "palette-classic"
      },
      "mappings": [],
      "thresholds": {
        "mode": "absolute",
        "steps": [
          {
            "value": null,
            "color": "green"
          },
          {
            "value": 80,
            "color": "red"
          }
        ]
      },
      "min": 0,
      "decimals": 0
    },
    "overrides": []
  },
  "description": "Number of blocks proven by each prover over time",
  "pluginVersion": "11.1.4"
}

[alexghr]

oh nice one