search

hashgraph / hedera-services

Crypto, token, consensus, file, and smart contract services for the Hedera public ledger
Apache License 2.0
266 stars 119 forks source link

Performance regression from debug logging #14018

Closed OlegMazurov closed 6 days ago

OlegMazurov commented 1 week ago

Description

The regression is caused by the following stack trace fragment:

DefaultHandleWorkflow.logUserTxn()
  DaggerHederaInjectionComponent$UserTransactionComponentImpl.txnInfo()
    PreHandleResultModule_ProvideTransactionInfoFactory.get()
      PreHandleResultModule_ProvidePreHandleResultFactory.get()
        PreHandleResultModule_ProvidePreHandleResultFactory.providePreHandleResult()
          PreHandleResultManager.getCurrentPreHandleResult()
            PreHandleWorkflowImpl.preHandleTransaction()

Although the actual logging is guarded by checking if logger.isDebugEnabled(), parameter evaluation happens outside the check. As the stack trace shows, that evaluation invokes transaction pre-handling, which is an expensive operation.

This is the only context [in a particular profile] where the txnInfo() method is invoked. It should be evaluated whether its [derived] implementation justifies such high cost.

Steps to reproduce

From performance testing of the develop branch in perf1.

Additional context

Introduced by #13804 or some relevant work.

Hedera network

other

Version

v0.52.0-SNAPSHOT

Operating system

Linux

Neeharika-Sompalli commented 1 week ago

Should be resolved by https://github.com/hashgraph/hedera-services/pull/13996. Dagger was providing the preHandleResult, which was first computed in the logger. I moved it to not be provided by Dagger.

Neeharika-Sompalli commented 6 days ago

Fixed by this PR https://github.com/hashgraph/hedera-services/pull/13996.