fix trace logs, avoid performance degradation

Gemfile.lock

@@ -3,7 +3,7 @@ PATH
   specs:
     ruby-ethereum (0.9.6)
       bitcoin-secp256k1 (~> 0.4)
-      block_logger (~> 0.1)
+      block_logger (>= 0.1.3)
       digest-sha3 (~> 1.1)
       ethash (~> 0.2)
       ffi (~> 1.9)
@@ -16,7 +16,7 @@ GEM
   specs:
     bitcoin-secp256k1 (0.4.0)
       ffi (>= 1.9.10)
-    block_logger (0.1.2)
+    block_logger (0.1.3)
       logging (~> 2.0)
     digest-sha3 (1.1.0)
     ethash (0.2.0)

lib/ethereum/db/level_db.rb

@@ -25,15 +25,15 @@ def reopen
       end
 
       def get(k)
-        logger.trace 'getting entry', key: Utils.encode_hex(k)[0,8]
+        logger.debug 'getting entry', key: Utils.encode_hex(k)[0,8]
 
         if @uncommited.has_key?(k)
           raise KeyError, 'key not in db' unless @uncommited[k]
-          logger.trace "from uncommited"
+          logger.debug "from uncommited"
           return @uncommited[k]
         end
 
-        logger.trace "from db"
+        logger.debug "from db"
         raise KeyError, k.inspect unless @db.exists?(k)
         v = @db.get(k)
         o = decompress v
@@ -43,7 +43,7 @@ def get(k)
       end
 
       def put(k, v)
-        logger.trace 'putting entry', key: Utils.encode_hex(k)[0,8], size: v.size
+        logger.debug 'putting entry', key: Utils.encode_hex(k)[0,8], size: v.size
         @uncommited[k] = v
       end
 
@@ -64,7 +64,7 @@ def commit
       end
 
       def delete(k)
-        logger.trace 'deleting entry', key: key
+        logger.debug 'deleting entry', key: key
         @uncommited[k] = nil
       end
 

lib/ethereum/db/refcount_db.rb

@@ -34,14 +34,14 @@ def inc_refcount(k, v)
         new_refcount = Utils.encode_int(refcount+1)
         ref_put k, RLP.encode([new_refcount, v])
 
-        if Logger.trace?(logger.name)
+        if logger.trace?
           logger.trace "increasing #{Utils.encode_hex(k)}=#{v} to #{refcount+1}"
         end
       rescue
         ref_put k, RLP.encode([ONE_ENCODED, v])
         @journal.push [ZERO_ENCODED, k]
 
-        if Logger.trace?(logger.name)
+        if logger.trace?
           logger.trace "increasing #{Utils.encode_hex(k)}=#{v} to 1"
         end
       end
@@ -54,7 +54,7 @@ def dec_refcount(k)
         node_object = RLP.decode ref_get(k)
         refcount = Utils.decode_int node_object[0]
 
-        if Logger.trace?(logger.name)
+        if logger.trace?
           logger.trace "decreasing #{Utils.encode_hex(k)} to #{refcount-1}"
         end
 

lib/ethereum/external_call.rb

@@ -151,9 +151,13 @@ def create(msg)
     def apply_msg(msg, code=nil)
       code ||= get_code msg.code_address
 
-      log_msg.debug "MSG APPLY",  sender: Utils.encode_hex(msg.sender), to: Utils.encode_hex(msg.to), gas: msg.gas, value: msg.value, data: Utils.encode_hex(msg.data.extract_all)
-      log_state.trace "MSG PRE STATE SENDER", account: Utils.encode_hex(msg.sender), balance: get_balance(msg.sender), state: log_storage(msg.sender)
-      log_state.trace "MSG PRE STATE RECIPIENT", account: Utils.encode_hex(msg.to), balance: get_balance(msg.to), state: log_storage(msg.to)
+      if log_msg.trace?
+        log_msg.debug "MSG APPLY",  sender: Utils.encode_hex(msg.sender), to: Utils.encode_hex(msg.to), gas: msg.gas, value: msg.value, data: Utils.encode_hex(msg.data.extract_all)
+        if log_state.trace?
+          log_state.trace "MSG PRE STATE SENDER", account: Utils.encode_hex(msg.sender), balance: get_balance(msg.sender), state: log_storage(msg.sender)
+          log_state.trace "MSG PRE STATE RECIPIENT", account: Utils.encode_hex(msg.to), balance: get_balance(msg.to), state: log_storage(msg.to)
+        end
+      end
 
       # snapshot before execution
       snapshot = self.snapshot
@@ -173,9 +177,13 @@ def apply_msg(msg, code=nil)
         res, gas, dat = VM.execute self, msg, code
       end
 
-      log_msg.trace "MSG APPLIED", gas_remained: gas, sender: msg.sender, to: msg.to, data: dat
-      log_state.trace "MSG POST STATE SENDER", account: Utils.encode_hex(msg.sender), balance: get_balance(msg.sender), state: log_storage(msg.sender)
-      log_state.trace "MSG POST STATE RECIPIENT", account: Utils.encode_hex(msg.to), balance: get_balance(msg.to), state: log_storage(msg.to)
+      if log_msg.trace?
+        log_msg.trace "MSG APPLIED", gas_remained: gas, sender: msg.sender, to: msg.to, data: dat
+        if log_state.trace?
+          log_state.trace "MSG POST STATE SENDER", account: Utils.encode_hex(msg.sender), balance: get_balance(msg.sender), state: log_storage(msg.sender)
+          log_state.trace "MSG POST STATE RECIPIENT", account: Utils.encode_hex(msg.to), balance: get_balance(msg.to), state: log_storage(msg.to)
+        end
+      end
 
       if res == 0
         log_msg.debug 'REVERTING'

lib/ethereum/fast_vm.rb

@@ -57,7 +57,7 @@ def execute(ext, msg, code)
         s.gas -= gas
 
         ops.each do |op|
-          if Logger.trace?(log_vm_exit.name)
+          if log_vm_exit.trace?
             trace_data = {
               stack: s.stack.map(&:to_s),
               inst: op,
@@ -573,12 +573,16 @@ def log_log
     end
 
     def vm_exception(error, **kwargs)
-      log_vm_exit.trace('EXCEPTION', cause: error, **kwargs)
+      if log_vm_exit.trace?
+        log_vm_exit.trace('EXCEPTION', cause: error, **kwargs)
+      end
       return 0, 0, []
     end
 
     def peaceful_exit(cause, gas, data, **kwargs)
-      log_vm_exit.trace('EXIT', cause: cause, **kwargs)
+      if log_vm_exit.trace?
+        log_vm_exit.trace('EXIT', cause: cause, **kwargs)
+      end
       return 1, gas, data
     end
 

lib/ethereum/vm.rb

@@ -49,7 +49,7 @@ def execute(ext, msg, code)
         # only to decide which features get logged in 'eth.vm.op', i.e.
         # tracing can not be activated by activating a sub like
         # 'eth.vm.op.stack'.
-        if Logger.trace?(log_vm_exit.name)
+        if log_vm_exit.trace?
           trace_data = {
             stack: s.stack.map(&:to_s),
             gas: s.gas + fee,
@@ -396,7 +396,9 @@ def execute(ext, msg, code)
 
           data = mem.safe_slice(mstart, msz)
           ext.log(msg.to, topics, Utils.int_array_to_bytes(data))
-          log_log.trace('LOG', to: msg.to, topics: topics, data: data)
+          if log_log.trace?
+            log_log.trace('LOG', to: msg.to, topics: topics, data: data)
+          end
         elsif op == :CREATE
           value, mstart, msz = stk.pop, stk.pop, stk.pop
 
@@ -582,12 +584,16 @@ def log_log
     end
 
     def vm_exception(error, **kwargs)
-      log_vm_exit.trace('EXCEPTION', cause: error, **kwargs)
+      if log_vm_exit.trace?
+        log_vm_exit.trace('EXCEPTION', cause: error, **kwargs)
+      end
       return 0, 0, []
     end
 
     def peaceful_exit(cause, gas, data, **kwargs)
-      log_vm_exit.trace('EXIT', cause: cause, **kwargs)
+      if log_vm_exit.trace?
+        log_vm_exit.trace('EXIT', cause: cause, **kwargs)
+      end
       return 1, gas, data
     end
 

ruby-ethereum.gemspec

@@ -20,7 +20,7 @@ Gem::Specification.new do |s|
   s.add_dependency('lru_redux', '~> 1.1')
   s.add_dependency('ffi', '~> 1.9')
   s.add_dependency('digest-sha3', '~> 1.1')
-  s.add_dependency('block_logger', '~> 0.1')
+  s.add_dependency('block_logger', '>= 0.1.3')
   s.add_dependency('leveldb', '0.1.9')
 
   s.add_development_dependency('rake', '~> 10.5')