diff --git a/src/bin/electrs.rs b/src/bin/electrs.rs index 0778ed18c..04ff38f8f 100644 --- a/src/bin/electrs.rs +++ b/src/bin/electrs.rs @@ -2,6 +2,7 @@ extern crate error_chain; #[macro_use] extern crate log; + extern crate electrs; use error_chain::ChainedError; @@ -116,6 +117,7 @@ fn run_server(config: Arc) -> Result<()> { let electrum_server = ElectrumRPC::start(Arc::clone(&config), Arc::clone(&query), &metrics); loop { + trace!("signal.wait"); if let Err(err) = signal.wait(Duration::from_secs(5), true) { info!("stopping server: {}", err); rest_server.stop(); @@ -123,19 +125,16 @@ fn run_server(config: Arc) -> Result<()> { break; } - debug!("checking for new blocks, current_tip={}", tip); - + trace!("calling getbestblockhash my tip={}", tip); // Index new blocks let current_tip = daemon.getbestblockhash()?; - debug!("new blockhash from bitcoind={}", current_tip); - if current_tip != tip { - debug!("updating index to {}", current_tip); + trace!("retrieved NEW blockhash bitcoind new={}", current_tip); indexer.update(&daemon)?; tip = current_tip; } else { - debug!("tip unchanged, no update"); + trace!("tip UNCHANGED") } // Update mempool @@ -152,9 +151,11 @@ fn run_server(config: Arc) -> Result<()> { } fn main() { + let config = Arc::new(Config::from_args()); if let Err(e) = run_server(config) { error!("server failed: {}", e.display_chain()); process::exit(1); } + } diff --git a/src/config.rs b/src/config.rs index 1220705da..86db0b4cb 100644 --- a/src/config.rs +++ b/src/config.rs @@ -388,6 +388,7 @@ impl Config { .map(|s| serde_json::from_str(s).expect("invalid --electrum-public-hosts")); let mut log = stderrlog::new(); + log.verbosity(m.occurrences_of("verbosity") as usize); log.timestamp(if m.is_present("timestamp") { stderrlog::Timestamp::Millisecond diff --git a/src/electrum/mod.rs b/src/electrum/mod.rs index 9e2eab4d0..406008bf2 100644 --- a/src/electrum/mod.rs +++ b/src/electrum/mod.rs @@ -13,20 +13,20 @@ use std::collections::HashMap; use std::str::FromStr; use serde::{de, Deserialize, Deserializer, Serialize}; -use std::time::Instant; +//use std::time::Instant; use crate::chain::BlockHash; use crate::errors::ResultExt; -use crate::util::{BlockId, log_fn_duration}; +use crate::util::{BlockId};//, log_fn_duration}; pub fn get_electrum_height(blockid: Option, has_unconfirmed_parents: bool) -> isize { - let t = Instant::now(); + // let t = Instant::now(); let res = match (blockid, has_unconfirmed_parents) { (Some(blockid), _) => blockid.height as isize, (None, false) => 0, (None, true) => -1, }; - log_fn_duration("electrum::mod::get_electrum_height", t.elapsed().as_micros()); +// log_fn_duration("electrum::mod::get_electrum_height", t.elapsed().as_micros()); res } diff --git a/src/electrum/server.rs b/src/electrum/server.rs index 891fd8097..5198be93e 100644 --- a/src/electrum/server.rs +++ b/src/electrum/server.rs @@ -25,7 +25,7 @@ use crate::errors::*; use crate::metrics::{Gauge, HistogramOpts, HistogramVec, MetricOpts, Metrics}; use crate::new_index::{Query, Utxo}; use crate::util::electrum_merkle::{get_header_merkle_proof, get_id_from_pos, get_tx_merkle_proof}; -use crate::util::{create_socket, spawn_thread, BlockId, BoolThen, Channel, FullHash, HeaderEntry, SyncChannel, log_fn_duration}; +use crate::util::{create_socket, spawn_thread, BlockId, BoolThen, Channel, FullHash, HeaderEntry, SyncChannel};//, log_fn_duration}; const ELECTRS_VERSION: &str = env!("CARGO_PKG_VERSION"); const PROTOCOL_VERSION: ProtocolVersion = ProtocolVersion::new(1, 4); @@ -36,12 +36,12 @@ use crate::electrum::{DiscoveryManager, ServerFeatures}; // TODO: Sha256dHash should be a generic hash-container (since script hash is single SHA256) fn hash_from_value(val: Option<&Value>) -> Result { - let t = Instant::now(); + // let t = Instant::now(); let script_hash = val.chain_err(|| "missing hash")?; let script_hash = script_hash.as_str().chain_err(|| "non-string hash")?; let script_hash = script_hash.parse().chain_err(|| "non-hex hash")?; let res = Ok(script_hash); - log_fn_duration("server::hash_from_value", t.elapsed().as_micros()); + // log_fn_duration("server::hash_from_value", t.elapsed().as_micros()); res } @@ -304,7 +304,7 @@ impl Connection { } fn blockchain_scripthash_get_history(&self, params: &[Value]) -> Result { - let t = Instant::now(); + // let t = Instant::now(); let script_hash = hash_from_value(params.get(0)).chain_err(|| "bad script_hash")?; let history_txids = get_history(&self.query, &script_hash[..], self.txs_limit)?; @@ -320,7 +320,7 @@ impl Connection { GetHistoryResult { txid, height, fee } }) .collect::>())); - log_fn_duration("server::blockchain_scripthash_get_history", t.elapsed().as_micros()); + // log_fn_duration("server::blockchain_scripthash_get_history", t.elapsed().as_micros()); res } @@ -669,10 +669,10 @@ fn get_history( scripthash: &[u8], txs_limit: usize, ) -> Result)>> { - let t = Instant::now(); + // let t = Instant::now(); // to avoid silently trunacting history entries, ask for one extra more than the limit and fail if it exists let history_txids = query.history_txids(scripthash, txs_limit + 1); - log_fn_duration("server::get_history", t.elapsed().as_micros()); + // log_fn_duration("server::get_history", t.elapsed().as_micros()); ensure!(history_txids.len() <= txs_limit, ErrorKind::TooPopular); Ok(history_txids) diff --git a/src/new_index/db.rs b/src/new_index/db.rs index 1efd0c3e9..2ae07ddf7 100644 --- a/src/new_index/db.rs +++ b/src/new_index/db.rs @@ -1,10 +1,10 @@ use rocksdb; use std::path::Path; -use std::time::Instant; +//use std::time::Instant; use crate::config::Config; -use crate::util::{bincode, Bytes, log_fn_duration}; +use crate::util::{bincode, Bytes};//, log_fn_duration}; static DB_VERSION: u32 = 1; @@ -132,12 +132,12 @@ impl DB { } pub fn iter_scan_from(&self, prefix: &[u8], start_at: &[u8]) -> ScanIterator { - let t = Instant::now(); + //let t = Instant::now(); let iter = self.db.iterator(rocksdb::IteratorMode::From( start_at, rocksdb::Direction::Forward, )); - log_fn_duration("db::iter_scan_from", t.elapsed().as_micros()); + //log_fn_duration("db::iter_scan_from", t.elapsed().as_micros()); ScanIterator { prefix: prefix.to_vec(), iter, diff --git a/src/new_index/mempool.rs b/src/new_index/mempool.rs index 0688424d7..1fb07c8b8 100644 --- a/src/new_index/mempool.rs +++ b/src/new_index/mempool.rs @@ -21,7 +21,7 @@ use crate::new_index::{ SpendingInfo, SpendingInput, TxHistoryInfo, Utxo, }; use crate::util::fees::{make_fee_histogram, TxFeeInfo}; -use crate::util::{extract_tx_prevouts, full_hash, has_prevout, is_spendable, Bytes, log_fn_duration}; +use crate::util::{extract_tx_prevouts, full_hash, has_prevout, is_spendable, Bytes};//, log_fn_duration}; #[cfg(feature = "liquid")] use crate::elements::asset; @@ -120,14 +120,14 @@ impl Mempool { } pub fn get_tx_fee(&self, txid: &Txid) -> Option { - let t = Instant::now(); + // let t = Instant::now(); let res = Some(self.feeinfo.get(txid)?.fee); - log_fn_duration("mempool::get_tx_fee", t.elapsed().as_micros()); + // log_fn_duration("mempool::get_tx_fee", t.elapsed().as_micros()); res } pub fn has_unconfirmed_parents(&self, txid: &Txid) -> bool { - let t = Instant::now(); + // let t = Instant::now(); let tx = match self.txstore.get(txid) { Some(tx) => tx, None => return false, @@ -135,7 +135,7 @@ impl Mempool { let res = tx.input .iter() .any(|txin| self.txstore.contains_key(&txin.previous_output.txid)); - log_fn_duration("mempool::has_unconfirmed_parents", t.elapsed().as_micros()); + // log_fn_duration("mempool::has_unconfirmed_parents", t.elapsed().as_micros()); res } @@ -158,7 +158,7 @@ impl Mempool { } pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec { - let t = Instant::now(); + // let t = Instant::now(); let _timer = self .latency .with_label_values(&["history_txids"]) @@ -172,7 +172,7 @@ impl Mempool { .take(limit) .collect() }; - log_fn_duration("mempool::history_txids", t.elapsed().as_micros()); + // log_fn_duration("mempool::history_txids", t.elapsed().as_micros()); res } @@ -306,7 +306,7 @@ impl Mempool { } fn add(&mut self, txs: Vec) { - let t = Instant::now(); + //let t = Instant::now(); self.delta .with_label_values(&["add"]) .observe(txs.len() as f64); @@ -415,7 +415,7 @@ impl Mempool { } pub fn lookup_txos(&self, outpoints: &BTreeSet) -> Result> { - let t = Instant::now(); + //let t = Instant::now(); let _timer = self .latency .with_label_values(&["lookup_txos"]) @@ -505,7 +505,7 @@ impl Mempool { } pub fn update(mempool: &Arc>, daemon: &Daemon) -> Result<()> { - let t = Instant::now(); + //let t = Instant::now(); let _timer = mempool.read().unwrap().latency.with_label_values(&["update"]).start_timer(); // 1. Determine which transactions are no longer in the daemon's mempool and which ones have newly entered it diff --git a/src/new_index/query.rs b/src/new_index/query.rs index 0a89e6ac9..81313e606 100644 --- a/src/new_index/query.rs +++ b/src/new_index/query.rs @@ -90,7 +90,7 @@ impl Query { } pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec<(Txid, Option)> { - let t = Instant::now(); + //let t = Instant::now(); let confirmed_txids = self.chain.history_txids(scripthash, limit); let confirmed_len = confirmed_txids.len(); let confirmed_txids = confirmed_txids.into_iter().map(|(tx, b)| (tx, Some(b))); @@ -102,7 +102,7 @@ impl Query { .map(|tx| (tx, None)); let res = confirmed_txids.chain(mempool_txids).collect(); - log_fn_duration("query::history_txids", t.elapsed().as_micros()); + //log_fn_duration("query::history_txids", t.elapsed().as_micros()); res } diff --git a/src/new_index/schema.rs b/src/new_index/schema.rs index 359fb5421..06902fd17 100644 --- a/src/new_index/schema.rs +++ b/src/new_index/schema.rs @@ -20,7 +20,7 @@ use elements::{ use std::collections::{BTreeSet, HashMap, HashSet}; use std::path::Path; use std::sync::{Arc, RwLock}; -use std::time::Instant; +//use std::time::Instant; use crate::chain::{ BlockHash, BlockHeader, Network, OutPoint, Script, Transaction, TxOut, Txid, Value, @@ -29,7 +29,7 @@ use crate::config::Config; use crate::daemon::Daemon; use crate::errors::*; use crate::metrics::{Gauge, HistogramOpts, HistogramTimer, HistogramVec, MetricOpts, Metrics}; -use crate::util::{bincode, full_hash, has_prevout, is_spendable, BlockHeaderMeta, BlockId, BlockMeta, BlockStatus, Bytes, HeaderEntry, HeaderList, ScriptToAddr, log_fn_duration}; +use crate::util::{bincode, full_hash, has_prevout, is_spendable, BlockHeaderMeta, BlockId, BlockMeta, BlockStatus, Bytes, HeaderEntry, HeaderList, ScriptToAddr};//, log_fn_duration}; use crate::new_index::db::{DBFlush, DBRow, ReverseScanIterator, ScanIterator, DB}; use crate::new_index::fetch::{start_fetcher, BlockEntry, FetchFrom}; @@ -455,12 +455,12 @@ impl ChainQuery { } pub fn history_iter_scan(&self, code: u8, hash: &[u8], start_height: usize) -> ScanIterator { - let t = Instant::now(); + // let t = Instant::now(); let res = self.store.history_db.iter_scan_from( &TxHistoryRow::filter(code, &hash[..]), &TxHistoryRow::prefix_height(code, &hash[..], start_height as u32), ); - log_fn_duration("chainquery::history_iter_scan", t.elapsed().as_micros()); + // log_fn_duration("chainquery::history_iter_scan", t.elapsed().as_micros()); res } fn history_iter_scan_reverse(&self, code: u8, hash: &[u8]) -> ReverseScanIterator { @@ -515,29 +515,29 @@ impl ChainQuery { } pub fn history_txids(&self, scripthash: &[u8], limit: usize) -> Vec<(Txid, BlockId)> { - let t = Instant::now(); + // let t = Instant::now(); // scripthash lookup let res = self._history_txids(b'H', scripthash, limit); - log_fn_duration("chainquery::history_txids", t.elapsed().as_micros()); + // log_fn_duration("chainquery::history_txids", t.elapsed().as_micros()); res } fn _history_txids(&self, code: u8, hash: &[u8], limit: usize) -> Vec<(Txid, BlockId)> { - let t = Instant::now(); - let _timer = self.start_timer("history_txids"); + // let t = Instant::now(); + // let _timer = self.start_timer("history_txids"); let res = self.history_iter_scan(code, hash, 0) .map(|row| TxHistoryRow::from_row(row).get_txid()) .unique() .filter_map(|txid| self.tx_confirming_block(&txid).map(|b| (txid, b))) .take(limit) .collect(); - log_fn_duration("chainquery::_history_txids", t.elapsed().as_micros()); + // log_fn_duration("chainquery::_history_txids", t.elapsed().as_micros()); res } // TODO: avoid duplication with stats/stats_delta? pub fn utxo(&self, scripthash: &[u8], limit: usize) -> Result> { - let _timer = self.start_timer("utxo"); + // let _timer = self.start_timer("utxo"); // get the last known utxo set and the blockhash it was updated for. // invalidates the cache if the block was orphaned. @@ -1053,14 +1053,14 @@ fn lookup_txos( allow_missing: bool, num_threads: usize, ) -> HashMap { - let t = Instant::now(); + //let t = Instant::now(); let pool = rayon::ThreadPoolBuilder::new() .num_threads(num_threads) // we need to saturate SSD IOPS .thread_name(|i| format!("lookup-txo-{}", i)) .build() .unwrap(); //log_fn_duration("schema::ThreadPoolBuilder", t.elapsed().as_micros()); - let t2 = Instant::now(); + //let t2 = Instant::now(); let res = pool.install(|| { outpoints .par_iter() @@ -1082,7 +1082,7 @@ fn lookup_txos( } fn lookup_txo(txstore_db: &DB, outpoint: &OutPoint) -> Option { - let t = Instant::now(); + //let t = Instant::now(); let res = txstore_db .get(&TxOutRow::key(&outpoint)) .map(|val| deserialize(&val).expect("failed to parse TxOut")); diff --git a/src/signal.rs b/src/signal.rs index 9bc30d9e3..612233722 100644 --- a/src/signal.rs +++ b/src/signal.rs @@ -52,7 +52,10 @@ impl Waiter { } } Ok(sig) => bail!(ErrorKind::Interrupt(sig)), - Err(RecvTimeoutError::Timeout) => Ok(()), + Err(RecvTimeoutError::Timeout) => { + trace!("timeout"); + Ok(()) + } Err(RecvTimeoutError::Disconnected) => bail!("signal hook channel disconnected"), } }