From 59f3dc3b6b8c6674b3c710acedf29e4309253e8e Mon Sep 17 00:00:00 2001 From: carllin Date: Wed, 30 Oct 2019 18:55:29 -0700 Subject: [PATCH] Fix PohRecorder Metrics (#6644) * Update Poh Recorder Dashboard * Update PohRecorder logging --- core/src/poh_recorder.rs | 37 +++++++++------ .../dashboards/testnet-monitor.json | 47 +++++++++++++++++-- 2 files changed, 65 insertions(+), 19 deletions(-) diff --git a/core/src/poh_recorder.rs b/core/src/poh_recorder.rs index 516b86b73..2d3107872 100644 --- a/core/src/poh_recorder.rs +++ b/core/src/poh_recorder.rs @@ -313,7 +313,7 @@ impl PohRecorder { let poh_entry = self.poh.lock().unwrap().tick(); inc_new_counter_warn!( "poh_recorder-tick_lock_contention", - timing::duration_as_ms(&now.elapsed()) as usize + timing::duration_as_us(&now.elapsed()) as usize ); let now = Instant::now(); if let Some(poh_entry) = poh_entry { @@ -323,7 +323,7 @@ impl PohRecorder { if self.leader_first_tick_height.is_none() { inc_new_counter_warn!( "poh_recorder-tick_overhead", - timing::duration_as_ms(&now.elapsed()) as usize + timing::duration_as_us(&now.elapsed()) as usize ); return; } @@ -339,7 +339,7 @@ impl PohRecorder { } inc_new_counter_warn!( "poh_recorder-tick_overhead", - timing::duration_as_ms(&now.elapsed()) as usize + timing::duration_as_us(&now.elapsed()) as usize ); } @@ -363,20 +363,29 @@ impl PohRecorder { return Err(Error::PohRecorderError(PohRecorderError::MaxHeightReached)); } - let now = Instant::now(); - if let Some(poh_entry) = self.poh.lock().unwrap().record(mixin) { + { + let now = Instant::now(); + let mut poh_lock = self.poh.lock().unwrap(); inc_new_counter_warn!( "poh_recorder-record_lock_contention", - timing::duration_as_ms(&now.elapsed()) as usize + timing::duration_as_us(&now.elapsed()) as usize ); - let entry = Entry { - num_hashes: poh_entry.num_hashes, - hash: poh_entry.hash, - transactions, - }; - self.sender - .send((working_bank.bank.clone(), (entry, self.tick_height)))?; - return Ok(()); + let now = Instant::now(); + let res = poh_lock.record(mixin); + inc_new_counter_warn!( + "poh_recorder-record_ms", + timing::duration_as_us(&now.elapsed()) as usize + ); + if let Some(poh_entry) = res { + let entry = Entry { + num_hashes: poh_entry.num_hashes, + hash: poh_entry.hash, + transactions, + }; + self.sender + .send((working_bank.bank.clone(), (entry, self.tick_height)))?; + return Ok(()); + } } // record() might fail if the next PoH hash needs to be a tick. But that's ok, tick() // and re-record() diff --git a/metrics/scripts/grafana-provisioning/dashboards/testnet-monitor.json b/metrics/scripts/grafana-provisioning/dashboards/testnet-monitor.json index 44ef83c4a..77f634c81 100644 --- a/metrics/scripts/grafana-provisioning/dashboards/testnet-monitor.json +++ b/metrics/scripts/grafana-provisioning/dashboards/testnet-monitor.json @@ -6335,7 +6335,7 @@ "x": 8, "y": 68 }, - "id": 46, + "id": 47, "legend": { "alignAsTable": false, "avg": false, @@ -6376,7 +6376,7 @@ ], "orderByTime": "ASC", "policy": "default", - "query": "SELECT sum(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-tick_lock_contention\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", + "query": "SELECT mean(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-tick_lock_contention\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", "rawQuery": true, "refId": "F", "resultFormat": "time_series", @@ -6413,7 +6413,7 @@ ], "orderByTime": "ASC", "policy": "default", - "query": "SELECT sum(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-record_lock_contention\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", + "query": "SELECT mean(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-record_lock_contention\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", "rawQuery": true, "refId": "A", "resultFormat": "time_series", @@ -6450,7 +6450,7 @@ ], "orderByTime": "ASC", "policy": "default", - "query": "SELECT sum(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-tick_overhead\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", + "query": "SELECT mean(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-tick_overhead\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", "rawQuery": true, "refId": "B", "resultFormat": "time_series", @@ -6469,6 +6469,43 @@ ] ], "tags": [] + }, + { + "groupBy": [ + { + "params": [ + "$__interval" + ], + "type": "time" + }, + { + "params": [ + "null" + ], + "type": "fill" + } + ], + "orderByTime": "ASC", + "policy": "default", + "query": "SELECT mean(\"count\") FROM \"$testnet\".\"autogen\".\"poh_recorder-record_ms\" WHERE host_id::tag =~ /$hostid/ AND $timeFilter GROUP BY time($__interval)", + "rawQuery": true, + "refId": "C", + "resultFormat": "time_series", + "select": [ + [ + { + "params": [ + "value" + ], + "type": "field" + }, + { + "params": [], + "type": "mean" + } + ] + ], + "tags": [] } ], "thresholds": [], @@ -6490,7 +6527,7 @@ }, "yaxes": [ { - "format": "ms", + "format": "µs", "label": null, "logBase": 1, "max": null,