From ab9067133cca8d1ca989e5a238b3d8f73ae6efd4 Mon Sep 17 00:00:00 2001 From: Jamie Lokier Date: Thu, 22 Jul 2021 14:35:41 +0100 Subject: [PATCH] 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 --- nimbus/p2p/executor/process_block.nim | 6 +++--- nimbus/p2p/executor/process_transaction.nim | 4 ++-- nimbus/vm/interpreter/gas_meter.nim | 6 +++--- nimbus/vm/interpreter/opcodes_impl.nim | 2 +- nimbus/vm/interpreter_dispatch.nim | 4 ++-- nimbus/vm/precompiles.nim | 10 +++++----- nimbus/vm2/interpreter/gas_meter.nim | 6 +++--- nimbus/vm2/interpreter/op_dispatcher.nim | 2 +- nimbus/vm2/interpreter/op_handlers/oph_call.nim | 12 ++++++------ nimbus/vm2/interpreter_dispatch.nim | 2 +- nimbus/vm2/precompiles.nim | 10 +++++----- 11 files changed, 32 insertions(+), 32 deletions(-) diff --git a/nimbus/p2p/executor/process_block.nim b/nimbus/p2p/executor/process_block.nim index 14e49d9c0..dcf4b0bfe 100644 --- a/nimbus/p2p/executor/process_block.nim +++ b/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: diff --git a/nimbus/p2p/executor/process_transaction.nim b/nimbus/p2p/executor/process_transaction.nim index 6c3cb3695..0aec90962 100644 --- a/nimbus/p2p/executor/process_transaction.nim +++ b/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 diff --git a/nimbus/vm/interpreter/gas_meter.nim b/nimbus/vm/interpreter/gas_meter.nim index 9a0fb4077..7c33f7be6 100644 --- a/nimbus/vm/interpreter/gas_meter.nim +++ b/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 diff --git a/nimbus/vm/interpreter/opcodes_impl.nim b/nimbus/vm/interpreter/opcodes_impl.nim index d1fa1e8c1..83da1fe60 100644 --- a/nimbus/vm/interpreter/opcodes_impl.nim +++ b/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 diff --git a/nimbus/vm/interpreter_dispatch.nim b/nimbus/vm/interpreter_dispatch.nim index ad818e789..0d2bea1d8 100644 --- a/nimbus/vm/interpreter_dispatch.nim +++ b/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 diff --git a/nimbus/vm/precompiles.nim b/nimbus/vm/precompiles.nim index 07ee3d4ae..65daa3ab2 100644 --- a/nimbus/vm/precompiles.nim +++ b/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) diff --git a/nimbus/vm2/interpreter/gas_meter.nim b/nimbus/vm2/interpreter/gas_meter.nim index 9a0fb4077..f065bbc21 100644 --- a/nimbus/vm2/interpreter/gas_meter.nim +++ b/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 diff --git a/nimbus/vm2/interpreter/op_dispatcher.nim b/nimbus/vm2/interpreter/op_dispatcher.nim index ebb0cd420..5c7bb063e 100644 --- a/nimbus/vm2/interpreter/op_dispatcher.nim +++ b/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) diff --git a/nimbus/vm2/interpreter/op_handlers/oph_call.nim b/nimbus/vm2/interpreter/op_handlers/oph_call.nim index bffe188d8..2a4a8b7bc 100644 --- a/nimbus/vm2/interpreter/op_handlers/oph_call.nim +++ b/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 diff --git a/nimbus/vm2/interpreter_dispatch.nim b/nimbus/vm2/interpreter_dispatch.nim index 5ec280378..653d2025c 100644 --- a/nimbus/vm2/interpreter_dispatch.nim +++ b/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) = diff --git a/nimbus/vm2/precompiles.nim b/nimbus/vm2/precompiles.nim index 85e94e250..47b453b83 100644 --- a/nimbus/vm2/precompiles.nim +++ b/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)