Fix block processing blowup, upgrade metrics (#500)

* Renamed fork_choice::process_attestation_from_block

* Processing attestation in fork choice

* Retrieving state from store and checking signature

* Looser check on beacon state validity.

* Cleaned up get_attestation_state

* Expanded fork choice api to provide latest validator message.

* Checking if the an attestation contains a latest message

* Correct process_attestation error handling.

* Copy paste error in comment fixed.

* Tidy ancestor iterators

* Getting attestation slot via helper method

* Refactored attestation creation in test utils

* Revert "Refactored attestation creation in test utils"

This reverts commit 4d277fe4239a7194758b18fb5c00dfe0b8231306.

* Integration tests for free attestation processing

* Implicit conflicts resolved.

* formatting

* Do first pass on Grants code

* Add another attestation processing test

* Tidy attestation processing

* Remove old code fragment

* Add non-compiling half finished changes

* Simplify, fix bugs, add tests for chain iters

* Remove attestation processing from op pool

* Fix bug with fork choice, tidy

* Fix overly restrictive check in fork choice.

* Ensure committee cache is build during attn proc

* Ignore unknown blocks at fork choice

* Various minor fixes

* Make fork choice write lock in to read lock

* Remove unused method

* Tidy comments

* Fix attestation prod. target roots change

* Fix compile error in store iters

* Reject any attestation prior to finalization

* Begin metrics refactor

* Move beacon_chain to new metrics structure.

* Make metrics not panic if already defined

* Use global prometheus gather at rest api

* Unify common metric fns into a crate

* Add heavy metering to block processing

* Remove hypen from prometheus metric name

* Add more beacon chain metrics

* Add beacon chain persistence metric

* Prune op pool on finalization

* Add extra prom beacon chain metrics

* Prefix BeaconChain metrics with "beacon_"

* Add more store metrics

* Add basic metrics to libp2p

* Add metrics to HTTP server

* Remove old `http_server` crate

* Update metrics names to be more like standard

* Fix broken beacon chain metrics, add slot clock metrics

* Add lighthouse_metrics gather fn

* Remove http args

* Fix wrong state given to op pool prune

* Make prom metric names more consistent

* Add more metrics, tidy existing metrics

* Fix store block read metrics

* Tidy attestation metrics

* Fix minor PR comments

* Allow travis failures on beta (see desc)

There's a non-backward compatible change in `cargo fmt`. Stable and beta
do not agree.

* Tidy `lighthouse_metrics` docs

* Fix typo

beacon_node/store/src/impls.rs

@@ -9,10 +9,26 @@ impl<T: EthSpec> StoreItem for BeaconBlock<T> {
     }
 
     fn as_store_bytes(&self) -> Vec<u8> {
-        self.as_ssz_bytes()
+        let timer = metrics::start_timer(&metrics::BEACON_BLOCK_WRITE_TIMES);
+        let bytes = self.as_ssz_bytes();
+
+        metrics::stop_timer(timer);
+        metrics::inc_counter(&metrics::BEACON_BLOCK_WRITE_COUNT);
+        metrics::inc_counter_by(&metrics::BEACON_BLOCK_WRITE_BYTES, bytes.len() as i64);
+
+        bytes
     }
 
     fn from_store_bytes(bytes: &mut [u8]) -> Result<Self, Error> {
-        Self::from_ssz_bytes(bytes).map_err(Into::into)
+        let timer = metrics::start_timer(&metrics::BEACON_BLOCK_READ_TIMES);
+
+        let len = bytes.len();
+        let result = Self::from_ssz_bytes(bytes).map_err(Into::into);
+
+        metrics::stop_timer(timer);
+        metrics::inc_counter(&metrics::BEACON_BLOCK_READ_COUNT);
+        metrics::inc_counter_by(&metrics::BEACON_BLOCK_READ_BYTES, len as i64);
+
+        result
     }
 }

beacon_node/store/src/impls/beacon_state.rs

@@ -53,12 +53,29 @@ impl<T: EthSpec> StoreItem for BeaconState<T> {
     }
 
     fn as_store_bytes(&self) -> Vec<u8> {
+        let timer = metrics::start_timer(&metrics::BEACON_STATE_WRITE_TIMES);
+
         let container = StorageContainer::new(self);
-        container.as_ssz_bytes()
+        let bytes = container.as_ssz_bytes();
+
+        metrics::stop_timer(timer);
+        metrics::inc_counter(&metrics::BEACON_STATE_WRITE_COUNT);
+        metrics::inc_counter_by(&metrics::BEACON_STATE_WRITE_BYTES, bytes.len() as i64);
+
+        bytes
     }
 
     fn from_store_bytes(bytes: &mut [u8]) -> Result<Self, Error> {
+        let timer = metrics::start_timer(&metrics::BEACON_STATE_READ_TIMES);
+
+        let len = bytes.len();
         let container = StorageContainer::from_ssz_bytes(bytes)?;
-        container.try_into()
+        let result = container.try_into();
+
+        metrics::stop_timer(timer);
+        metrics::inc_counter(&metrics::BEACON_STATE_READ_COUNT);
+        metrics::inc_counter_by(&metrics::BEACON_STATE_READ_BYTES, len as i64);
+
+        result
     }
 }

beacon_node/store/src/leveldb_store.rs

@@ -1,4 +1,5 @@
 use super::*;
+use crate::metrics;
 use db_key::Key;
 use leveldb::database::kv::KV;
 use leveldb::database::Database;
@@ -62,15 +63,27 @@ impl Store for LevelDB {
     fn get_bytes(&self, col: &str, key: &[u8]) -> Result<Option<Vec<u8>>, Error> {
         let column_key = Self::get_key_for_col(col, key);
 
-        self.db
+        metrics::inc_counter(&metrics::DISK_DB_READ_COUNT);
+
+        let result = self
+            .db
             .get(self.read_options(), column_key)
-            .map_err(Into::into)
+            .map_err(Into::into);
+
+        if let Ok(Some(bytes)) = &result {
+            metrics::inc_counter_by(&metrics::DISK_DB_READ_BYTES, bytes.len() as i64)
+        }
+
+        result
     }
 
     /// Store some `value` in `column`, indexed with `key`.
     fn put_bytes(&self, col: &str, key: &[u8], val: &[u8]) -> Result<(), Error> {
         let column_key = Self::get_key_for_col(col, key);
 
+        metrics::inc_counter(&metrics::DISK_DB_WRITE_COUNT);
+        metrics::inc_counter_by(&metrics::DISK_DB_WRITE_BYTES, val.len() as i64);
+
         self.db
             .put(self.write_options(), column_key, val)
             .map_err(Into::into)
@@ -80,6 +93,8 @@ impl Store for LevelDB {
     fn key_exists(&self, col: &str, key: &[u8]) -> Result<bool, Error> {
         let column_key = Self::get_key_for_col(col, key);
 
+        metrics::inc_counter(&metrics::DISK_DB_EXISTS_COUNT);
+
         self.db
             .get(self.read_options(), column_key)
             .map_err(Into::into)
@@ -89,6 +104,9 @@ impl Store for LevelDB {
     /// Removes `key` from `column`.
     fn key_delete(&self, col: &str, key: &[u8]) -> Result<(), Error> {
         let column_key = Self::get_key_for_col(col, key);
+
+        metrics::inc_counter(&metrics::DISK_DB_DELETE_COUNT);
+
         self.db
             .delete(self.write_options(), column_key)
             .map_err(Into::into)

beacon_node/store/src/lib.rs

@@ -7,18 +7,22 @@
 //!
 //! Provides a simple API for storing/retrieving all types that sometimes needs type-hints. See
 //! tests for implementation examples.
+#[macro_use]
+extern crate lazy_static;
 
 mod block_at_slot;
 mod errors;
 mod impls;
 mod leveldb_store;
 mod memory_store;
+mod metrics;
 
 pub mod iter;
 
 pub use self::leveldb_store::LevelDB as DiskStore;
 pub use self::memory_store::MemoryStore;
 pub use errors::Error;
+pub use metrics::scrape_for_metrics;
 pub use types::*;
 
 /// An object capable of storing and retrieving objects implementing `StoreItem`.

beacon_node/store/src/metrics.rs

@@ -0,0 +1,106 @@
+pub use lighthouse_metrics::{set_gauge, try_create_int_gauge, *};
+
+use std::fs;
+use std::path::PathBuf;
+
+lazy_static! {
+    /*
+     * General
+     */
+    pub static ref DISK_DB_SIZE: Result<IntGauge> =
+        try_create_int_gauge("store_disk_db_size", "Size of the on-disk database (bytes)");
+    pub static ref DISK_DB_WRITE_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_write_bytes_total",
+        "Number of bytes attempted to be written to the on-disk DB"
+    );
+    pub static ref DISK_DB_READ_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_read_bytes_total",
+        "Number of bytes read from the on-disk DB"
+    );
+    pub static ref DISK_DB_READ_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_read_count_total",
+        "Total number of reads to the on-disk DB"
+    );
+    pub static ref DISK_DB_WRITE_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_write_count_total",
+        "Total number of writes to the on-disk DB"
+    );
+    pub static ref DISK_DB_EXISTS_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_exists_count_total",
+        "Total number of checks if a key is in the on-disk DB"
+    );
+    pub static ref DISK_DB_DELETE_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_disk_db_delete_count_total",
+        "Total number of deletions from the on-disk DB"
+    );
+    /*
+     * Beacon State
+     */
+    pub static ref BEACON_STATE_READ_TIMES: Result<Histogram> = try_create_histogram(
+        "store_beacon_state_read_overhead_seconds",
+        "Overhead on reading a beacon state from the DB (e.g., decoding)"
+    );
+    pub static ref BEACON_STATE_READ_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_state_read_total",
+        "Total number of beacon state reads from the DB"
+    );
+    pub static ref BEACON_STATE_READ_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_state_read_bytes_total",
+        "Total number of beacon state bytes read from the DB"
+    );
+    pub static ref BEACON_STATE_WRITE_TIMES: Result<Histogram> = try_create_histogram(
+        "store_beacon_state_write_overhead_seconds",
+        "Overhead on writing a beacon state to the DB (e.g., encoding)"
+    );
+    pub static ref BEACON_STATE_WRITE_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_state_write_total",
+        "Total number of beacon state writes the DB"
+    );
+    pub static ref BEACON_STATE_WRITE_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_state_write_bytes_total",
+        "Total number of beacon state bytes written to the DB"
+    );
+    /*
+     * Beacon Block
+     */
+    pub static ref BEACON_BLOCK_READ_TIMES: Result<Histogram> = try_create_histogram(
+        "store_beacon_block_read_overhead_seconds",
+        "Overhead on reading a beacon block from the DB (e.g., decoding)"
+    );
+    pub static ref BEACON_BLOCK_READ_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_block_read_total",
+        "Total number of beacon block reads from the DB"
+    );
+    pub static ref BEACON_BLOCK_READ_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_block_read_bytes_total",
+        "Total number of beacon block bytes read from the DB"
+    );
+    pub static ref BEACON_BLOCK_WRITE_TIMES: Result<Histogram> = try_create_histogram(
+        "store_beacon_block_write_overhead_seconds",
+        "Overhead on writing a beacon block to the DB (e.g., encoding)"
+    );
+    pub static ref BEACON_BLOCK_WRITE_COUNT: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_block_write_total",
+        "Total number of beacon block writes the DB"
+    );
+    pub static ref BEACON_BLOCK_WRITE_BYTES: Result<IntCounter> = try_create_int_counter(
+        "store_beacon_block_write_bytes_total",
+        "Total number of beacon block bytes written to the DB"
+    );
+}
+
+/// Updates the global metrics registry with store-related information.
+pub fn scrape_for_metrics(db_path: &PathBuf) {
+    let db_size = if let Ok(iter) = fs::read_dir(db_path) {
+        iter.filter_map(std::result::Result::ok)
+            .map(size_of_dir_entry)
+            .fold(0_u64, |sum, val| sum + val)
+    } else {
+        0
+    };
+    set_gauge(&DISK_DB_SIZE, db_size as i64);
+}
+
+fn size_of_dir_entry(dir: fs::DirEntry) -> u64 {
+    dir.metadata().map(|m| m.len()).unwrap_or(0)
+}