Tracing: Remove some trace messages that occur a lot during sync

Disable some trace messages which appeared a lot in the output and probably
aren't so useful any more, when block processing is functioning well at high
speed.

Turning on the trace level globally is useful to get a feel for what's
happening, but only if each category is kept to a reasonable amount.

As well as overwhelming the output so that it's hard to see general activity,
some of these messages happen so much they severely slow down processing.  Ones
called every time an EVM opcode uses some gas are particularly extreme.

These messages have all been chosen as things which are probably not useful any
more (the relevant functionality has been debugged and is tested plenty).

These have been commented out rather than removed.  It may be that turning
trace topics on/off, or other selection, is a better longer term solution, but
that will require better command line options and good defaults for sure.
(I think higher levels `tracev` and `tracevv` levels (extra verbose) would be
more useful for this sort of deep tracing on request.)

For now, enabling `--log-level:TRACE` on the command line is quite useful as
long as we keep each category reasonable, and this patch tries to keep that
balance.

- Don't show "has transactions" on virtually every block imported.
- Don't show "Sender" and "txHash" lines on every transaction processed.
- Don't show "GAS CONSUMPTION" on every opcode executed", this is way too much.
- Don't show "GAS RETURNED" and "GAS REFUND" on each contract call.
- Don't show "op: Stop" on every Stop opcode, which means every transaction.
- Don't show "Insufficient funds" whenever a contract can't call another.
- Don't show "ECRecover", "SHA256 precompile", "RIPEMD160", "Identity"
  or even "Call precompile" every time a precompile is called.  These are
  very well tested now.
- Don't show "executeOpcodes error" whenever a contract returns an error.
  (This is changed to `trace` too, it's a normal event that is well tested.)

Signed-off-by: Jamie Lokier <[email protected]>

nimbus/p2p/executor/process_block.nim

@@ -50,9 +50,9 @@ proc procBlkPreamble(vmState: BaseVMState; dbTx: DbTransaction;
  blockNumber = header.blockNumber
  return false
  else:
- trace "Has transactions",
- blockNumber = header.blockNumber,
- blockHash = header.blockHash
+ #trace "Has transactions",
+ # blockNumber = header.blockNumber,
+ # blockHash = header.blockHash
  vmState.receipts = newSeq[Receipt](body.transactions.len)
  vmState.cumulativeGasUsed = 0
  for txIndex, tx in body.transactions:

nimbus/p2p/executor/process_transaction.nim

@@ -37,8 +37,8 @@ proc processTransactionImpl(tx: Transaction, sender: EthAddress,
  vmState: BaseVMState, fork: Fork): GasInt
  # wildcard exception, wrapped below
  {.gcsafe, raises: [Exception].} =
- trace "Sender", sender
- trace "txHash", rlpHash = tx.rlpHash
+ #trace "Sender", sender
+ #trace "txHash", rlpHash = tx.rlpHash
 
  var tx = eip1559TxNormalization(tx)
  var priorityFee: GasInt

nimbus/vm/interpreter/gas_meter.nim

@@ -21,12 +21,12 @@ proc consumeGas*(gasMeter: var GasMeter; amount: GasInt; reason: string) =
  raise newException(OutOfGas,
  &"Out of gas: Needed {amount} - Remaining {gasMeter.gasRemaining} - Reason: {reason}")
  gasMeter.gasRemaining -= amount
- trace "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason
+# trace "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason
 
 proc returnGas*(gasMeter: var GasMeter; amount: GasInt) =
  gasMeter.gasRemaining += amount
- trace "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining
+# trace "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining
 
 proc refundGas*(gasMeter: var GasMeter; amount: GasInt) =
  gasMeter.gasRefunded += amount
- trace "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded
+# trace "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded

nimbus/vm/interpreter/opcodes_impl.nim

@@ -827,7 +827,7 @@ template genCall(callName: untyped, opCode: Op): untyped =
  when opCode in {CallCode, Call}:
  let senderBalance = c.getBalance(sender)
  if senderBalance < value:
- debug "Insufficient funds", available = senderBalance, needed = c.msg.value
+ #debug "Insufficient funds", available = senderBalance, needed = c.msg.value
  # return unused gas
  c.gasMeter.returnGas(childGasLimit)
  return

nimbus/vm/interpreter_dispatch.nim

@@ -267,7 +267,7 @@ proc opTableToCaseStmt(opTable: array[Op, NimNode], c: NimNode): NimNode =
  let branchStmt = block:
  if op == Stop:
  quote do:
- trace "op: Stop"
+ #trace "op: Stop"
  if not `c`.code.atEnd() and `c`.tracingEnabled:
  # we only trace `REAL STOP` and ignore `FAKE STOP`
  `c`.opIndex = `c`.traceOpCodeStarted(`asOp`)
@@ -416,4 +416,4 @@ proc executeOpcodes(c: Computation) =
 
  if c.isError() and c.continuation.isNil:
  if c.tracingEnabled: c.traceError()
- debug "executeOpcodes error", msg=c.error.info
+ #trace "executeOpcodes error", msg=c.error.info

nimbus/vm/precompiles.nim

@@ -120,7 +120,7 @@ proc ecRecover*(computation: Computation) =
 
  computation.output.setLen(32)
  computation.output[12..31] = pubkey[].toCanonicalAddress()
- trace "ECRecover precompile", derivedKey = pubkey[].toCanonicalAddress()
+ #trace "ECRecover precompile", derivedKey = pubkey[].toCanonicalAddress()
 
 proc sha256*(computation: Computation) =
  let
@@ -129,7 +129,7 @@ proc sha256*(computation: Computation) =
 
  computation.gasMeter.consumeGas(gasFee, reason="SHA256 Precompile")
  computation.output = @(nimcrypto.sha_256.digest(computation.msg.data).data)
- trace "SHA256 precompile", output = computation.output.toHex
+ #trace "SHA256 precompile", output = computation.output.toHex
 
 proc ripemd160*(computation: Computation) =
  let
@@ -139,7 +139,7 @@ proc ripemd160*(computation: Computation) =
  computation.gasMeter.consumeGas(gasFee, reason="RIPEMD160 Precompile")
  computation.output.setLen(32)
  computation.output[12..31] = @(nimcrypto.ripemd160.digest(computation.msg.data).data)
- trace "RIPEMD160 precompile", output = computation.output.toHex
+ #trace "RIPEMD160 precompile", output = computation.output.toHex
 
 proc identity*(computation: Computation) =
  let
@@ -148,7 +148,7 @@ proc identity*(computation: Computation) =
 
  computation.gasMeter.consumeGas(gasFee, reason="Identity Precompile")
  computation.output = computation.msg.data
- trace "Identity precompile", output = computation.output.toHex
+ #trace "Identity precompile", output = computation.output.toHex
 
 proc modExpInternal(computation: Computation, baseLen, expLen, modLen: int, T: type StUint) =
  template data: untyped {.dirty.} =
@@ -683,7 +683,7 @@ proc execPrecompiles*(computation: Computation, fork: Fork): bool {.inline.} =
  if lb in PrecompileAddresses.low.byte .. maxPrecompileAddr.byte:
  result = true
  let precompile = PrecompileAddresses(lb)
- trace "Call precompile", precompile = precompile, codeAddr = computation.msg.codeAddress
+ #trace "Call precompile", precompile = precompile, codeAddr = computation.msg.codeAddress
  try:
  case precompile
  of paEcRecover: ecRecover(computation)

nimbus/vm2/interpreter/gas_meter.nim

@@ -21,12 +21,12 @@ proc consumeGas*(gasMeter: var GasMeter; amount: GasInt; reason: string) =
  raise newException(OutOfGas,
  &"Out of gas: Needed {amount} - Remaining {gasMeter.gasRemaining} - Reason: {reason}")
  gasMeter.gasRemaining -= amount
- trace "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason
+ #trace "GAS CONSUMPTION", total = gasMeter.gasRemaining + amount, amount, remaining = gasMeter.gasRemaining, reason
 
 proc returnGas*(gasMeter: var GasMeter; amount: GasInt) =
  gasMeter.gasRemaining += amount
- trace "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining
+ #trace "GAS RETURNED", consumed = gasMeter.gasRemaining - amount, amount, remaining = gasMeter.gasRemaining
 
 proc refundGas*(gasMeter: var GasMeter; amount: GasInt) =
  gasMeter.gasRefunded += amount
- trace "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded
+ #trace "GAS REFUND", consumed = gasMeter.gasRemaining - amount, amount, refunded = gasMeter.gasRefunded

nimbus/vm2/interpreter/op_dispatcher.nim

@@ -36,7 +36,7 @@ export
 # ------------------------------------------------------------------------------
 
 template handleStopDirective(k: var Vm2Ctx) =
- trace "op: Stop"
+ #trace "op: Stop"
  if not k.cpt.code.atEnd() and k.cpt.tracingEnabled:
  # we only trace `REAL STOP` and ignore `FAKE STOP`
  k.cpt.opIndex = k.cpt.traceOpCodeStarted(Stop)

nimbus/vm2/interpreter/op_handlers/oph_call.nim

@@ -212,9 +212,9 @@ const
 
  let senderBalance = k.cpt.getBalance(p.sender)
  if senderBalance < p.value:
- debug "Insufficient funds",
- available = senderBalance,
- needed = k.cpt.msg.value
+ #debug "Insufficient funds",
+ # available = senderBalance,
+ # needed = k.cpt.msg.value
  k.cpt.gasMeter.returnGas(childGasLimit)
  return
 
@@ -278,9 +278,9 @@ const
 
  let senderBalance = k.cpt.getBalance(p.sender)
  if senderBalance < p.value:
- debug "Insufficient funds",
- available = senderBalance,
- needed = k.cpt.msg.value
+ #debug "Insufficient funds",
+ # available = senderBalance,
+ # needed = k.cpt.msg.value
  k.cpt.gasMeter.returnGas(childGasLimit)
  return
 

nimbus/vm2/interpreter_dispatch.nim

@@ -204,7 +204,7 @@ proc executeOpcodes*(c: Computation) =
 
  if c.isError() and c.continuation.isNil:
  if c.tracingEnabled: c.traceError()
- debug "executeOpcodes error", msg=c.error.info
+ #trace "executeOpcodes error", msg=c.error.info
 
 
 proc execCallOrCreate*(cParam: Computation) =

nimbus/vm2/precompiles.nim

@@ -130,7 +130,7 @@ proc ecRecover*(computation: Computation) =
 
  computation.output.setLen(32)
  computation.output[12..31] = pubkey[].toCanonicalAddress()
- trace "ECRecover precompile", derivedKey = pubkey[].toCanonicalAddress()
+ #trace "ECRecover precompile", derivedKey = pubkey[].toCanonicalAddress()
 
 proc sha256*(computation: Computation) =
  let
@@ -139,7 +139,7 @@ proc sha256*(computation: Computation) =
 
  computation.gasMeter.consumeGas(gasFee, reason="SHA256 Precompile")
  computation.output = @(nimcrypto.sha_256.digest(computation.msg.data).data)
- trace "SHA256 precompile", output = computation.output.toHex
+ #trace "SHA256 precompile", output = computation.output.toHex
 
 proc ripemd160*(computation: Computation) =
  let
@@ -149,7 +149,7 @@ proc ripemd160*(computation: Computation) =
  computation.gasMeter.consumeGas(gasFee, reason="RIPEMD160 Precompile")
  computation.output.setLen(32)
  computation.output[12..31] = @(nimcrypto.ripemd160.digest(computation.msg.data).data)
- trace "RIPEMD160 precompile", output = computation.output.toHex
+ #trace "RIPEMD160 precompile", output = computation.output.toHex
 
 proc identity*(computation: Computation) =
  let
@@ -158,7 +158,7 @@ proc identity*(computation: Computation) =
 
  computation.gasMeter.consumeGas(gasFee, reason="Identity Precompile")
  computation.output = computation.msg.data
- trace "Identity precompile", output = computation.output.toHex
+ #trace "Identity precompile", output = computation.output.toHex
 
 proc modExpInternal(computation: Computation, baseLen, expLen, modLen: int, T: type StUint) =
  template data: untyped {.dirty.} =
@@ -693,7 +693,7 @@ proc execPrecompiles*(computation: Computation, fork: Fork): bool {.inline.} =
  if lb in PrecompileAddresses.low.byte .. maxPrecompileAddr.byte:
  result = true
  let precompile = PrecompileAddresses(lb)
- trace "Call precompile", precompile = precompile, codeAddr = computation.msg.codeAddress
+ #trace "Call precompile", precompile = precompile, codeAddr = computation.msg.codeAddress
  try:
  case precompile
  of paEcRecover: ecRecover(computation)