chain: keep track of processing time for blocks.

lib/bcoin/chain.js

@@ -78,6 +78,7 @@ function Chain(options) {
   this.synced = false;
   this.state = new DeploymentState();
   this.stateCache = {};
+  this._time = utils.hrtime();
 
   this.orphan = {
     map: {},
@@ -103,18 +104,6 @@ Chain.prototype._init = function _init() {
     self.logger.warning('Warning: %dmb of pending objects. Purging.', utils.mb(size));
   });
 
-  // Hook into events for debugging
-  this.on('block', function(block, entry) {
-    if (!self.synced && self.height < self.network.block.slowHeight)
-      return;
-
-    if (self.options.spv)
-      return;
-
-    self.logger.info('Block %s (%d) added to chain.',
-      entry.rhash, entry.height);
-  });
-
   this.on('competitor', function(block, entry) {
     self.logger.warning('Heads up: Competing chain at height %d:'
       + ' tip-height=%d competitor-height=%d'
@@ -1336,7 +1325,6 @@ Chain.prototype.isBusy = function isBusy() {
 
 Chain.prototype.add = function add(block, callback, force) {
   var self = this;
-  var total = 0;
   var ret = {};
   var unlock;
 
@@ -1351,10 +1339,11 @@ Chain.prototype.add = function add(block, callback, force) {
 
   (function next(block, initial) {
     var hash = block.hash('hex');
-    var prevHash = block.prevBlock;
+    var prevBlock = block.prevBlock;
     var height, checkpoint, orphan, entry;
 
     self.currentBlock = hash;
+    self._mark();
 
     function handleOrphans() {
       // No orphan chain.
@@ -1372,7 +1361,7 @@ Chain.prototype.add = function add(block, callback, force) {
     }
 
     // Do not revalidate known invalid blocks.
-    if (self.invalid[hash] || self.invalid[prevHash]) {
+    if (self.invalid[hash] || self.invalid[prevBlock]) {
       self.emit('invalid', block, block.getCoinbaseHeight());
       self.invalid[hash] = true;
       return done(new VerifyError(block, 'duplicate', 'duplicate', 100));
@@ -1386,7 +1375,7 @@ Chain.prototype.add = function add(block, callback, force) {
 
     // If the block is already known to be
     // an orphan, ignore it.
-    orphan = self.orphan.map[prevHash];
+    orphan = self.orphan.map[prevBlock];
     if (orphan) {
       // The orphan chain forked.
       if (orphan.hash('hex') !== hash) {
@@ -1425,7 +1414,7 @@ Chain.prototype.add = function add(block, callback, force) {
       }
 
       // Find the previous block height/index.
-      self.db.get(prevHash, function(err, prev) {
+      self.db.get(prevBlock, function(err, prev) {
         if (err)
           return done(err);
 
@@ -1441,7 +1430,7 @@ Chain.prototype.add = function add(block, callback, force) {
         if (!prev) {
           self.orphan.count++;
           self.orphan.size += block.getSize();
-          self.orphan.map[prevHash] = block;
+          self.orphan.map[prevBlock] = block;
           self.orphan.bmap[hash] = block;
 
           // Update the best height based on the coinbase.
@@ -1516,9 +1505,8 @@ Chain.prototype.add = function add(block, callback, force) {
             if (err)
               return done(err);
 
-            // Keep track of the number of blocks we
-            // added and the number of orphans resolved.
-            total++;
+            // Keep track of stats.
+            self._done(block, entry);
 
             // Emit our block (and potentially resolved
             // orphan) only if it is on the main chain.
@@ -1536,9 +1524,8 @@ Chain.prototype.add = function add(block, callback, force) {
           if (err)
             return done(err);
 
-          // Keep track of the number of blocks we
-          // added and the number of orphans resolved.
-          total++;
+          // Keep track of stats.
+          self._done(block, entry);
 
           // Emit our block (and potentially resolved
           // orphan) only if it is on the main chain.
@@ -1560,15 +1547,6 @@ Chain.prototype.add = function add(block, callback, force) {
     if (self.orphan.size > self.orphanLimit)
       self.pruneOrphans();
 
-    // Keep track of total blocks handled.
-    self.total += total;
-
-    // Report memory for debugging.
-    if (self.total === 1 || self.total % 20 === 0) {
-      utils.gc();
-      self.logger.memory();
-    }
-
     utils.nextTick(function() {
       if (!self.synced && self.isFull()) {
         self.synced = true;
@@ -1577,14 +1555,69 @@ Chain.prototype.add = function add(block, callback, force) {
 
       self.currentBlock = null;
 
-      if (err)
-        callback(err);
-      else
-        callback(null, total);
+      callback(err);
     });
   }
 };
 
+/**
+ * Test whether the chain has reached its slow height.
+ * @private
+ * @returns {Boolean}
+ */
+
+Chain.prototype._isSlow = function _isSlow() {
+  if (this.options.spv)
+    return false;
+
+  if (this.total === 1 || this.total % 20 === 0)
+    return true;
+
+  return this.synced || this.height >= this.network.block.slowHeight;
+};
+
+/**
+ * Mark the start time for block processing.
+ * @private
+ */
+
+Chain.prototype._mark = function _mark() {
+  this._time = utils.hrtime();
+};
+
+/**
+ * Calculate the time difference from
+ * start time and log block.
+ * @private
+ * @param {Block} block
+ * @param {ChainEntry} entry
+ */
+
+Chain.prototype._done = function _done(block, entry) {
+  var elapsed, time;
+
+  // Keep track of total blocks handled.
+  this.total += 1;
+
+  if (!this._isSlow())
+    return;
+
+  // Report memory for debugging.
+  utils.gc();
+  this.logger.memory();
+
+  elapsed = utils.hrtime(this._time);
+  time = elapsed[0] * 1000 + elapsed[1] / 1e6;
+
+  this.logger.info(
+    'Block %s (%d) added to chain (size=%d, txs=%d time=%d).',
+    entry.rhash,
+    entry.height,
+    block.getSize(),
+    block.txs.length,
+    time);
+};
+
 /**
  * Purge any waiting orphans.
  */

lib/bcoin/pool.js

@@ -893,11 +893,10 @@ Pool.prototype._handleBlock = function _handleBlock(block, peer, callback) {
 
     if (self.logger.level === 4 && self.chain.total % 20 === 0) {
       self.logger.debug('Status:'
-        + ' tip=%s ts=%s height=%d progress=%s'
+        + ' ts=%s height=%d progress=%s'
         + ' blocks=%d orphans=%d active=%d'
         + ' queue=%d target=%s peers=%d'
         + ' pending=%d highest=%d jobs=%d',
-        block.rhash,
         utils.date(block.ts),
         self.chain.height,
         (self.chain.getProgress() * 100).toFixed(2) + '%',

lib/bcoin/protocol/network.js

@@ -286,7 +286,7 @@ main.block = {
    * logs without spamming.
    */
 
-  slowHeight: 400000
+  slowHeight: 325000
 };
 
 /**

lib/bcoin/utils.js

@@ -383,6 +383,29 @@ utils.getMerkleBranch = crypto.getMerkleBranch;
 
 utils.checkMerkleBranch = crypto.checkMerkleBranch;
 
+/**
+ * Return hrtime (shim for browser).
+ * @param {Array} time
+ * @returns {Array}
+ */
+
+utils.hrtime = function hrtime(time) {
+  var now, ms, sec;
+
+  if (utils.isBrowser) {
+    now = utils.ms();
+    if (time) {
+      time = time[0] * 1000 + time[1] / 1e6;
+      now -= time;
+    }
+    ms = now % 1000;
+    sec = (now - ms) / 1000;
+    return [sec, ms * 1e6];
+  }
+
+  return process.hrtime(time);
+};
+
 /**
  * Test whether a string is hex. Note that this
  * _could_ yield a false positive on base58