Profiling patch

gistfile1.rb

diff --git a/lib/toshi/processor.rb b/lib/toshi/processor.rb
index 87fa835..8b775aa 100644
--- a/lib/toshi/processor.rb
+++ b/lib/toshi/processor.rb
@@ -87,6 +87,7 @@ module Toshi
         @output_cache.flush
         missing_inputs_exception = nil
 
+        start_time = Time.now
         @storage.transaction do
           begin
             accepted = self.accept_to_memory_pool(tx, false, raise_errors)
@@ -95,12 +96,17 @@ module Toshi
             @mempool.add_orphan_tx(tx)
           end
         end
+        log_raw_tx_events(tx.hash, "accept to mempool time: #{(Time.now - start_time).to_f}")
 
         if accepted
           # Recursively process any orphan transactions that depended on this one
+          start_time = Time.now
           relay_transaction_to_peers(tx)
+          log_raw_tx_events(tx.hash, "relay tx time: #{(Time.now - start_time).to_f}")
           work_queue = [ tx.hash ]
           i = 0
+          orphans_resurrected = 0
+          start_time = Time.now
           while i < work_queue.length do
             @mempool.get_orphan_txs_by_prev_hash(work_queue[i]).each do |orphan_tx|
               orphan_accepted = false
@@ -115,6 +121,7 @@ module Toshi
                 end
                 if orphan_accepted
                   # orphan is no longer an orphan, see if it's a parent
+                  orphans_resurrected += 1
                   work_queue << orphan_tx.hash
                   relay_transaction_to_peers(orphan_tx)
                 end
@@ -122,6 +129,7 @@ module Toshi
             end
             i += 1
           end
+          log_raw_tx_events(tx.hash, "orphan(#{orphans_resurrected}) resurrection time: #{(Time.now - start_time).to_f}")
         end
 
         @output_cache.flush
@@ -180,27 +188,40 @@ module Toshi
         end
       end
 
+      log_raw_tx_events(tx.hash, "context-free check time: #{(Time.now - start_time).to_f}")
+
       # Lock access to the memory pool for the remainder of the db transaction.
       @mempool.lock
 
+      start_time = Time.now
+
       # Is it already in the memory pool?
       if @mempool.exists?(tx.binary_hash)
         raise TxValidationError, "AcceptToMemoryPool() : already in the memory pool"
         return false
       end
 
+      log_raw_tx_events(tx.hash, "in-mempool check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Check for conflicts with in-memory transactions
       if @mempool.any_inputs_spent?(tx)
         raise TxValidationError, "AcceptToMemoryPool() : already spent in the memory pool"
         return false
       end
 
+      log_raw_tx_events(tx.hash, "spent-in-mempool check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Check to see if we have the tx on the main branch or the memory pool already.
       if !expect_tip && @mempool.exists_including_main_branch?(tx.binary_hash)
         raise TxValidationError, "AcceptToMemoryPool() : transaction already seen"
         return false
       end
 
+      log_raw_tx_events(tx.hash, "exists-including-tip check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Do all inputs exist?
       # Note that this does not check for the presence of actual outputs (see the next check for that),
       # only helps filling in pfMissingInputs (to determine missing vs spent).
@@ -212,9 +233,15 @@ module Toshi
         end
       end
 
+      log_raw_tx_events(tx.hash, "missing inputs check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Bulk load the output cache from the db with the relevant outputs.
       @storage.load_output_cache([tx]) if !on_disconnect
 
+      log_raw_tx_events(tx.hash, "load output cache time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Are the actual inputs available?
       if !self.verify_inputs_are_available(tx, include_memory_pool=true)
         raise TxValidationError, "AcceptToMemoryPool() : inputs already spent"
@@ -224,6 +251,9 @@ module Toshi
         return false
       end
 
+      log_raw_tx_events(tx.hash, "inputs are available check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Check for non-standard pay-to-script-hash in inputs
 
       if require_standard?
@@ -233,6 +263,9 @@ module Toshi
         end
       end
 
+      log_raw_tx_events(tx.hash, "inputs are standard check time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       # Note: if you modify this code to accept non-standard transactions, then
       # you should add code here to check that the transaction does a
       # reasonable number of ECDSA signature verifications.
@@ -248,9 +281,13 @@ module Toshi
         return false
       end
 
+      log_raw_tx_events(tx.hash, "check inputs time: #{(Time.now - start_time).to_f}")
+      start_time = Time.now
+
       logger.debug{ "tx #{tx.hash} accepted to memory pool" }
       @mempool.add_unchecked(tx, on_disconnect)
 
+      log_raw_tx_events(tx.hash, "add unchecked time: #{(Time.now - start_time).to_f}")
       return true
     rescue TxValidationError => ex
       logger.warn{ "tx rejected: #{ex.message}" } if !raise_errors