feat: JSON logging

[spalladino]

Adds a LOG_JSON env var that disables the foundation logger and replaces it with a winston json logger.

{"level":"info","message":"Set block interval to 12","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.509Z"}
{"level":"info","message":"Deploying contracts from 0xf39Fd6e51aad88F6F4ce6aB8827279cffFb92266...","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.509Z"}
{"level":"info","message":"Deployed Registry at 0x3aa5ebb10dc797cac828524e59a333d0a371443c","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.534Z"}
{"level":"info","message":"Deployed AvailabilityOracle at 0xc6e7df5e7b4f2a278906862b61205850344d4e7d","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.551Z"}
{"level":"info","message":"Deployed Fee Juice at 0x59b670e9fa9d0a427751af201d676719a970857b","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.563Z"}
{"level":"info","message":"Deployed Gas Portal at 0x4ed7c70f96b99c776995fb64377f0d4ab3b0e1c1","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.573Z"}
{"level":"info","message":"Funded fee juice portal contract with Fee Juice","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.582Z"}
{"level":"info","message":"Initialized Gas Portal at 0x4ed7c70f96b99c776995fb64377f0d4ab3b0e1c1 to bridge between L1 0x59b670e9fa9d0a427751af201d676719a970857b to L2 0x16a83e3395bc921a2441db55dce24f0e0932636901a2e676fa68b9b2b9a644c1","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.591Z"}
{"level":"info","message":"Deployed Rollup at 0x4a679253410272dd5232b3ff7cf5dbb88f295319","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.608Z"}
{"level":"info","message":"Inbox available at 0x532b02bd614fd18aee45603d02866cfb77575cb3","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.610Z"}
{"level":"info","message":"Outbox available at 0xe801273f775eacc1d74d1d43f92ec4524cabbd35","module":"aztec:sandbox","timestamp":"2024-08-21T02:15:29.612Z"}
{"level":"info","message":"Using NoopTelemetryClient","module":"aztec:telemetry-client","timestamp":"2024-08-21T02:15:29.644Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:node:lmdb","timestamp":"2024-08-21T02:15:29.645Z"}
{"level":"info","message":"Performing initial chain sync to rollup contract 0x4a679253410272dd5232b3ff7cf5dbb88f295319","module":"aztec:archiver","timestamp":"2024-08-21T02:15:29.661Z"}
{"level":"info","message":"Synced to L1 block 27","module":"aztec:archiver","timestamp":"2024-08-21T02:15:29.672Z"}
{"level":"info","message":"Started block downloader from block 1","module":"aztec:world_state","timestamp":"2024-08-21T02:15:29.743Z"}
{"level":"info","message":"Using WASM ACVM simulation","module":"aztec:node","timestamp":"2024-08-21T02:15:29.744Z"}
{"level":"info","message":"Sequencer started","module":"aztec:sequencer","timestamp":"2024-08-21T02:15:29.745Z"}
{"level":"info","message":"Started Aztec Node against chain 0x7a69 with contracts - \nRollup: 0x4a679253410272dd5232b3ff7cf5dbb88f295319\nRegistry: 0x3aa5ebb10dc797cac828524e59a333d0a371443c\nInbox: 0x532b02bd614fd18aee45603d02866cfb77575cb3\nOutbox: 0xe801273f775eacc1d74d1d43f92ec4524cabbd35\nAvailability Oracle: 0xc6e7df5e7b4f2a278906862b61205850344d4e7d","module":"aztec:node","timestamp":"2024-08-21T02:15:29.746Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:kv-store","timestamp":"2024-08-21T02:15:29.753Z"}
{"level":"info","message":"Creating ephemeral data store","module":"aztec:kv-store","timestamp":"2024-08-21T02:15:29.760Z"}
{"level":"info","message":"Added contract ContractClassRegisterer at 0x05d15342d76e46e5be07d3cda0d753158431cdc5e39d29ce4e8fe1f5c070564a","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.795Z"}
{"level":"info","message":"Added contract ContractInstanceDeployer at 0x2ab1a2bd6d07d8d61ea56d85861446349e52c6b7c0612b702cb1e6db6ad0b089","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.802Z"}
{"level":"info","message":"Added contract MultiCallEntrypoint at 0x0e028bd5acf2e33f647132af47ce05a37a022c3f7a51bb426271bd6764bc0aaf","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.811Z"}
{"level":"info","message":"Added contract FeeJuice at 0x16a83e3395bc921a2441db55dce24f0e0932636901a2e676fa68b9b2b9a644c1","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.820Z"}
{"level":"info","message":"Added contract NewKeyRegistry at 0x2ee3f8c67efa88f9e6fb44242f1e9dcc0f9a6752ded07af0d9fac3875a61d421","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.827Z"}
{"level":"info","message":"Added contract AuthRegistry at 0x24877c50868f86712240eb535d90d1c97403d074805dd3758c3aecb02958f8d4","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.834Z"}
{"level":"info","message":"Initial sync complete","module":"aztec:pxe_synchronizer","timestamp":"2024-08-21T02:15:29.836Z"}
{"level":"info","message":"Started PXE connected to chain 31337 version 1","module":"aztec:pxe_service","timestamp":"2024-08-21T02:15:29.849Z"}
{"level":"info","message":"Aztec Server listening on port 8080","module":"aztec:cli","timestamp":"2024-08-21T02:15:29.852Z"}
{"level":"info","message":"Shutting down...","module":"aztec:cli","timestamp":"2024-08-21T02:15:49.618Z"}

[AztecBot]

Benchmark results

Metrics with a significant change:

• protocol_circuit_simulation_time_in_ms (private-kernel-tail-to-public): 778 (-44%)
• avm_simulation_time_ms (FeeJuice:set_portal): 12.6 (+30%)
• avm_simulation_time_ms (Token:transfer_public): 19.6 (-39%)

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,779	1,567	712	743 (-3%)	775
proof_construction_time_sha256_30_ms	11,571 (+1%)	3,099	1,384	1,440	1,471
proof_construction_time_sha256_100_ms	44,142	11,882	5,461 (+1%)	5,657 (+5%)	5,726
proof_construction_time_poseidon_hash_ms	79.0	34.0	34.0	57.0 (-3%)	87.0 (-1%)
proof_construction_time_poseidon_hash_30_ms	1,533	423	203	229	273 (+2%)
proof_construction_time_poseidon_hash_100_ms	5,664	1,516	680 (+1%)	743 (+2%)	743 (-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,324	7,844	14,852
l1_rollup_calldata_gas	49,684	92,474	177,428
l1_rollup_execution_gas	1,373,712	2,107,398	3,892,408
l2_block_processing_time_in_ms	261 (+7%)	442 (+2%)	837 (+2%)
l2_block_building_time_in_ms	8,905 (-2%)	17,495	34,693 (-2%)
l2_block_rollup_simulation_time_in_ms	8,905 (-2%)	17,494	34,693 (-2%)
l2_block_public_tx_process_time_in_ms	7,528 (-2%)	15,982	33,109 (-2%)

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	2,910	3,800 (+2%)
node_database_size_in_bytes	12,599,376 (-1%)	16,715,856
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	84.7 (-5%)	381 (-7%)	21,755	44,860	N/A
private-kernel-inner	172 (+4%)	679 (-4%)	72,566	45,007	N/A
private-kernel-reset-tiny	460 (-1%)	844 (-3%)	65,675	44,846	N/A
private-kernel-tail	195 (-1%)	151 (-4%)	50,686	52,257	N/A
base-parity	5.58 (-1%)	N/A	160	96.0	N/A
root-parity	35.1 (-1%)	N/A	73,948	96.0	N/A
base-rollup	2,747	N/A	189,136	664	N/A
root-rollup	40.0 (-1%)	N/A	58,173	716	N/A
public-kernel-setup	83.5 (-2%)	N/A	105,085	71,222	N/A
public-kernel-app-logic	95.2	N/A	104,911	71,222	N/A
public-kernel-tail	550 (-1%)	N/A	410,534	16,414	N/A
private-kernel-reset-small	456 (-1%)	N/A	66,341	45,629	N/A
private-kernel-tail-to-public	:warning: 778 (-44%)	627 (-3%)	460,796	1,825	N/A
public-kernel-teardown	81.7 (-1%)	N/A	105,349	71,222	N/A
merge-rollup	20.0	N/A	38,174	664	N/A
undefined	N/A	N/A	N/A	N/A	82,921 (+5%)

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	344 (+1%)
ContractInstanceDeployer:deploy	1,408	11,731	18.1 (-2%)
MultiCallEntrypoint:entrypoint	1,920	11,731	405
FeeJuice:deploy	1,376	11,731	387
SchnorrAccount:constructor	1,312	11,731	74.4 (-2%)
SchnorrAccount:entrypoint	2,304	11,731	410 (-1%)
Token:privately_mint_private_note	1,280	11,731	103 (-3%)
FPC:fee_entrypoint_public	1,344	11,731	26.5 (-10%)
Token:transfer	1,312	11,731	230 (-2%)
Benchmarking:create_note	1,344	11,731	85.3 (-5%)
SchnorrAccount:verify_private_authwit	1,280	11,731	27.6 (+1%)
Token:unshield	1,376	11,731	526 (+1%)
FPC:fee_entrypoint_private	1,376	11,731	705 (+2%)

AVM Simulation

Time to simulate various public functions in the AVM.

Function	time_ms	bytecode_size_in_bytes
FeeJuice:_increase_public_balance	55.8	7,739
FeeJuice:set_portal	:warning: 12.6 (+30%)	2,354
Token:constructor	82.2 (+5%)	26,051
FPC:constructor	55.1 (+3%)	18,001
FeeJuice:mint_public	38.6 (-2%)	5,877
Token:mint_public	50.5 (+11%)	10,917
Token:assert_minter_and_mint	67.5 (+2%)	7,512
AuthRegistry:set_authorized	39.4 (-17%)	4,391
FPC:prepare_fee	230	7,043
Token:transfer_public	:warning: 19.6 (-39%)	39,426
FPC:pay_refund	51.8 (-11%)	10,234
Benchmarking:increment_balance	931	6,563
Token:_increase_public_balance	40.6	8,433
FPC:pay_refund_with_shielded_rebate	65.1 (+2%)	10,783

Public DB Access

Time to access various public DBs.

Function	time_ms
get-nullifier-index	0.163 (+4%)

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.16 (-1%)	3.83 (-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.111 (-1%)	0.107 (-2%)	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	17.6 (-2%)	31.3 (+2%)	58.2 (-1%)	111 (-3%)
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 (-1%)	0.102 (-2%)	0.101 (+1%)	0.100 (-1%)	0.100 (-1%)
batch_insert_into_indexed_tree_20_depth_ms	N/A	N/A	14.4	25.9	44.0 (+1%)	81.6 (-1%)	160
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.109	0.103 (-2%)	0.107 (+1%)	0.101 (-1%)	0.101
batch_insert_into_indexed_tree_40_depth_ms	N/A	N/A	16.3	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.104 (-1%)	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 | | | - | |