metrics: incorrect write_time counter for insert_decided_block in store.rs

[ikwuoz]

arc-node/crates/consensus-db/src/store.rs

Lines 457 to 490 in a85368c

	fn insert_decided_block(
	&self,
	decided_block: DecidedBlock,
	proposer: Address,
	) -> Result<(), StoreError> {
	let start = Instant::now();
	let mut write_bytes = 0;
	let height = decided_block.height();
	let tx = self.db.begin_write()?;
	{
	let mut blocks = tx.open_table(DECIDED_BLOCKS_TABLE)?;
	let block_bytes = encode_execution_payload(&decided_block.execution_payload);
	#[allow(clippy::arithmetic_side_effects)]
	{
	write_bytes += block_bytes.len();
	}
	blocks.insert(height, block_bytes)?;
	}
	self.insert_certificate(
	&tx,
	decided_block.certificate,
	CommitCertificateType::Minimal,
	Some(proposer),
	)?;
	tx.commit()?;
	self.update_write_metrics(write_bytes, start.elapsed());
	Ok(())
	}

In insert_decided_block above, start.elapsed() spans the entire function body including insert_certificate(), which itself calls update_write_metrics with its own internal timer, then:

1. The write time in insert_decided_block is for block bytes, but it ends up including the write time for certificate bytes,
2. However insert_certificate also reports its own write time internally.

Therefore, the certificate insertion time is double counted in the aggregated write_time metric because both calls accumulate into the same counter.

Impact: The write latency metric overstates actual DB write time by roughly one cert encoding + insert cycle per insert_decided_block call, causing metric inaccuracy.

[osr21]

Confirmed the diagnosis against the code at a85368c0 — and the impact is actually broader than the issue states, in two ways worth recording before this closes:

1. It's not just write_time — write_count and write_bytes throughput are also inflated. update_write_metrics both observes the latency histogram and increments write_count via add_write_bytes. So every decided block was counted as two write operations, not one write with padded latency. Anyone deriving writes/sec or bytes-per-write from these metrics on a full node sees roughly double the true decided-block write rate (decided blocks dominate the write workload on a following node). The latency skew described here is real, but the throughput overstatement is arguably the more misleading of the two for capacity planning.

2. One subtle point in the original framing: the double-count isn't "block write time + a second cert observation" — it's two separate histogram observations, one spanning block+cert+commit (from insert_decided_block) and one spanning just the cert insert without the commit (from inside insert_certificate). Since the second observation excludes the commit/fsync — the dominant cost — it lands in the histogram's low buckets, dragging the apparent median down while the count doubles. So the aggregate write_time sum overstates, but percentile views (p50) of the histogram can actually understate real write latency. If anyone tried to reconcile these metrics with disk-level I/O timing and found them incoherent in both directions, this is why.

Status: PR #228 fixes this with the right ownership model — insert_certificate returns bytes and records nothing; the method that commits the transaction makes the single metrics call, measured through the commit. As of 06fcbd1 it also brings extend_certificate (the other caller, whose old measurement silently excluded commit cost) onto the same convention, and both paths are pinned by regression tests asserting write_count +1 per committed transaction. I've reviewed the full diff there; once CI is green it's a complete close of this issue.

Post-merge note for ops dashboards: expect a step change in these metrics after upgrading — write_count rate roughly halves, write_time p50 jumps up (the artificial low-bucket observations disappear). Both movements are the metrics becoming truthful, not a regression; worth a heads-up to anyone with alerting thresholds on consensus-DB write latency.