perf: unnecessary call to arweave.networkInfo when block height is re…

README.md

@@ -16,6 +16,7 @@ To further improve contract state evaluation time, one can additionally use AWS
 - [Development](#development)
   - [Installation and import](#installation-and-import)
   - [Using the RedStone Gateway](#using-the-redstone-gateway)
+  - [Performance - best practices](#performance---best-practices)
   - [Examples](#examples)
   - [Migration guide](#migration-guide)
   - [Documentation](#documentation)
@@ -114,6 +115,46 @@ const smartweave = SmartWeaveNodeFactory.memCachedBased(arweave)
 
 More examples can be found [here](https://github.com/redstone-finance/redstone-smartcontracts-examples/blob/main/src/redstone-gateway-example.ts).
 
+### Performance - best practices
+In order to get the best performance on production environment (or while performing benchmarks ;-)), please follow these simple rules:
+1. Do NOT use the `TsLoggerFactory` - it is good for development, as it formats the logs nicely, but might slow down the state evaluation
+by a factor of 2 or 3 (depending on the logging level).
+2. Use `fatal` or `error` log level, e.g.:
+```ts
+// configure the logging first
+LoggerFactory.INST.logLevel("fatal");
+// or
+LoggerFactory.INST.logLevel("error");
+
+// then create an instance of smartweave sdk
+const smartweave = SmartWeaveWebFactory.memCached(arweave);
+```
+Logging on `info` or `debug` level is good for development, but turning it on globally might slow down the evaluation by a factor of 2.  
+Keep in mind that you can fine tune the log level of each module separately. For example you can switch the `fatal` globally, but `debug`
+for the `ArweaveGatewayInteractionsLoader` (in order to verify the load times from Arweave GQL endpoint). The names of the modules are derived from the
+names of TypeScript classes, e.g.:
+```ts
+// configure the logging first
+LoggerFactory.INST.logLevel("fatal");
+LoggerFactory.INST.logLevel("debug", "ArweaveGatewayInteractionsLoader");
+
+// then create an instance of smartweave sdk
+const smartweave = SmartWeaveWebFactory.memCached(arweave);
+```
+
+3. If your contract does not make any `readContractState` calls (i.e. it is not reading other contracts' state), you can switch the 
+`updateCacheForEachInteraction` flag to `false` - this will limit the amounts of writes to the state cache (and therefore decrease the execution time for such contracts), e.g.:
+```ts
+// create an instance of smartweave sdk
+const smartweave = SmartWeaveWebFactory.memCached(arweave);
+
+// then connect it to a given contract with "updateCacheForEachInteraction" set to "false"
+const contract = smartweave.contract(contractTxId).setEvaluationOptions({
+    updateCacheForEachInteraction: false
+  });
+```
+
+
 ### Examples
 Usage examples can be found in
 a dedicated [repository](https://github.com/redstone-finance/redstone-smartcontracts-examples).

package.json

@@ -70,6 +70,8 @@
     "@typescript-eslint/parser": "^4.29.2",
     "arlocal": "1.1.13",
     "cheerio": "^1.0.0-rc.10",
+    "cli-table": "0.3.11",
+    "colors": "^1.4.0",
     "cors": "^2.8.5",
     "eslint": "^7.32.0",
     "eslint-config-prettier": "^8.3.0",
@@ -79,6 +81,8 @@
     "jest": "^27.4.3",
     "prettier": "^2.3.2",
     "rimraf": "^3.0.2",
+    "safe-stable-stringify": "2.3.1",
+    "simple-statistics": "^7.7.0",
     "smartweave": "0.4.45",
     "sqlite3": "^5.0.2",
     "ts-jest": "^27.0.7",

src/__tests__/regression/read-state.test.ts

@@ -5,6 +5,8 @@ import { interactRead, readContract } from 'smartweave';
 import Arweave from 'arweave';
 import { LoggerFactory, SmartWeaveNodeFactory } from '@smartweave';
 
+const stringify = require('safe-stable-stringify')
+
 function* chunks(arr, n) {
   for (let i = 0; i < arr.length; i += n) {
     // note: wrapping with an array to make it compatible with describe.each
@@ -34,10 +36,10 @@ describe.each(chunked)('.suite %#', (contracts: string[]) => {
     async (contractTxId: string) => {
       console.log('readContract', contractTxId);
       const result = await readContract(arweave, contractTxId);
-      const resultString = JSON.stringify(result).trim();
+      const resultString = stringify(result).trim();
       console.log('readState', contractTxId);
       const result2 = await SmartWeaveNodeFactory.memCached(arweave, 1).contract(contractTxId).readState();
-      const result2String = JSON.stringify(result2.state).trim();
+      const result2String = stringify(result2.state).trim();
       expect(result2String).toEqual(resultString);
     },
     600000
@@ -49,13 +51,13 @@ describe('readState', () => {
     const contractTxId = 'CbGCxBJn6jLeezqDl1w3o8oCSeRCb-MmtZNKPodla-0';
     const blockHeight = 707892;
     const result = await readContract(arweave, contractTxId, blockHeight);
-    const resultString = JSON.stringify(result).trim();
+    const resultString = stringify(result).trim();
 
     const result2 = await SmartWeaveNodeFactory.memCached(arweave, 1)
       .contract(contractTxId)
       .setEvaluationOptions({ updateCacheForEachInteraction: false })
       .readState(blockHeight);
-    const result2String = JSON.stringify(result2.state).trim();
+    const result2String = stringify(result2.state).trim();
 
     expect(result2String).toEqual(resultString);
   });

src/__tests__/regression/test-cases/read-state.json

@@ -1,5 +1,6 @@
 [
   "Daj-MNSnH55TDfxqC7v4eq0lKzVIwh98srUaWqyuZtY",
+  "t9T7DIOGxx4VWXoCEeYYarFYeERTpWIC1V3y-BPZgKE",
   "5pSyVjFI07z8mbLeQhYBMsQ4M_MPidXIGX6T77rnF2s",
   "-8A6RexFkpfWwuyVO98wzSFZh0d6VJuI-buTJvlwOJQ",
   "AVTqjPQGCCXim7Nl_gn3HMjE4k0Zi_eTFRJCNEVXZxw",
@@ -86,7 +87,6 @@
   "2caOW6ol9T8LHCMO8tVAx4GHRwv1q3fFc79KzKOtoww",
   "HdZBZa0GfOEUYCubwvoSyxGUUgPmgy7RJb5l77T21bE",
   "7Dp5r-UpZLDvHqsDbZbqWhCBwbYdJMKBuC3tFC-FF7U",
-  "YLVpmhSq5JmLltfg6R-5fL04rIRPrlSU22f6RQ6VyYE",
   "EOtTxCGktZe_J2DTM0D5h04crjlpjgeygA1R6Pmo_qM",
   "92Tq6BKm6pvVkKW8_6Fb13QWTdUzBRLnG9scMBNWYZ4",
   "w27141UQGgrCFhkiw9tL7A0-qWMQjbapU3mq2TfI4Cg",

src/cache/impl/MemBlockHeightCache.ts

@@ -63,8 +63,6 @@ export class MemBlockHeightSwCache<V = any> implements BlockHeightSwCache<V> {
       cached.delete(toRemove);
     }
 
-    // note: "value" should be deep copied here for safety
-    // but it significantly degrades overall performance...
     cached.set(blockHeight, value);
   }
 

src/contract/Contract.ts

@@ -11,6 +11,7 @@ import {
 import { NetworkInfoInterface } from 'arweave/node/network';
 
 export type CurrentTx = { interactionTxId: string; contractTxId: string };
+export type BenchmarkStats = { gatewayCommunication: number; stateEvaluation: number; total: number };
 
 /**
  * A base interface to be implemented by SmartWeave Contracts clients
@@ -146,7 +147,7 @@ export interface Contract<State = unknown> {
    * "root" contract network info - so that the whole execution is performed with the
    * same network info)
    */
-  getNetworkInfo(): NetworkInfoInterface;
+  getNetworkInfo(): Partial<NetworkInfoInterface>;
 
   /**
    * Get the block height requested by user for the given interaction with contract
@@ -175,4 +176,9 @@ export interface Contract<State = unknown> {
    * the same as the evaluation options of the root contract.
    */
   evaluationOptions(): EvaluationOptions;
+
+  /**
+   * returns benchmark results for the last performed readState call
+   */
+  lastReadStateStats(): BenchmarkStats;
 }

src/contract/HandlerBasedContract.ts

@@ -2,6 +2,7 @@ import {
   ArTransfer,
   ArWallet,
   Benchmark,
+  BenchmarkStats,
   Contract,
   ContractCallStack,
   ContractInteraction,
@@ -45,14 +46,16 @@ export class HandlerBasedContract<State> implements Contract<State> {
    * Only the 'root' contract call should read this data from Arweave - all the inner calls ("child" contracts)
    * should reuse this data from the parent ("calling") contract.
    */
-  private _networkInfo?: NetworkInfoInterface = null;
+  private _networkInfo?: Partial<NetworkInfoInterface> = null;
 
   private _rootBlockHeight: number = null;
 
   private readonly _innerWritesEvaluator = new InnerWritesEvaluator();
 
   private readonly _callDepth: number;
 
+  private _benchmarkStats: BenchmarkStats = null;
+
   /**
    * wallet connected to this contract
    */
@@ -98,21 +101,36 @@ export class HandlerBasedContract<State> implements Contract<State> {
       contractTxId: this._contractTxId,
       currentTx
     });
+    const initBenchmark = Benchmark.measure();
     this.maybeResetRootContract(blockHeight);
 
     const { stateEvaluator } = this.smartweave;
-    const benchmark = Benchmark.measure();
     const executionContext = await this.createExecutionContext(this._contractTxId, blockHeight);
     this.logger.info('Execution Context', {
       blockHeight: executionContext.blockHeight,
       srcTxId: executionContext.contractDefinition?.srcTxId,
       missingInteractions: executionContext.sortedInteractions.length,
       cachedStateHeight: executionContext.cachedState?.cachedHeight
     });
-    this.logger.debug('context', benchmark.elapsed());
-    benchmark.reset();
+    initBenchmark.stop();
+
+    const stateBenchmark = Benchmark.measure();
     const result = await stateEvaluator.eval(executionContext, currentTx || []);
-    this.logger.debug('state', benchmark.elapsed());
+    stateBenchmark.stop();
+
+    const total = (initBenchmark.elapsed(true) as number) + (stateBenchmark.elapsed(true) as number);
+
+    this._benchmarkStats = {
+      gatewayCommunication: initBenchmark.elapsed(true) as number,
+      stateEvaluation: stateBenchmark.elapsed(true) as number,
+      total
+    };
+
+    this.logger.info('Benchmark', {
+      'Gateway communication  ': initBenchmark.elapsed(),
+      'Contract evaluation    ': stateBenchmark.elapsed(),
+      'Total:                 ': `${total.toFixed(0)}ms`
+    });
     return result as EvalStateResult<State>;
   }
 
@@ -232,7 +250,7 @@ export class HandlerBasedContract<State> implements Contract<State> {
     return this._callStack;
   }
 
-  getNetworkInfo(): NetworkInfoInterface {
+  getNetworkInfo(): Partial<NetworkInfoInterface> {
     return this._networkInfo;
   }
 
@@ -281,9 +299,15 @@ export class HandlerBasedContract<State> implements Contract<State> {
     const benchmark = Benchmark.measure();
     // if this is a "root" call (ie. original call from SmartWeave's client)
     if (this._parentContract == null) {
-      this.logger.debug('Reading network info for root call');
-      currentNetworkInfo = await arweave.network.getInfo();
-      this._networkInfo = currentNetworkInfo;
+      if (blockHeight) {
+        this._networkInfo = {
+          height: blockHeight
+        };
+      } else {
+        this.logger.debug('Reading network info for root call');
+        currentNetworkInfo = await arweave.network.getInfo();
+        this._networkInfo = currentNetworkInfo;
+      }
     } else {
       // if that's a call from within contract's source code
       this.logger.debug('Reusing network info from the calling contract');
@@ -300,7 +324,6 @@ export class HandlerBasedContract<State> implements Contract<State> {
       blockHeight = currentNetworkInfo.height;
     }
     this.logger.debug('network info', benchmark.elapsed());
-
     benchmark.reset();
 
     const cachedState = await stateEvaluator.latestAvailableState<State>(contractTxId, blockHeight);
@@ -309,6 +332,9 @@ export class HandlerBasedContract<State> implements Contract<State> {
       cachedBlockHeight = cachedState.cachedHeight;
     }
 
+    this.logger.debug('cache lookup', benchmark.elapsed());
+    benchmark.reset();
+
     let contractDefinition,
       interactions = [],
       sortedInteractions = [],
@@ -557,4 +583,8 @@ export class HandlerBasedContract<State> implements Contract<State> {
   evaluationOptions(): EvaluationOptions {
     return this._evaluationOptions;
   }
+
+  lastReadStateStats(): BenchmarkStats {
+    return this._benchmarkStats;
+  }
 }

src/core/index.ts

@@ -7,6 +7,7 @@ export * from './modules/CreateContract';
 
 export * from './modules/impl/BlockHeightInteractionsSorter';
 export * from './modules/impl/ContractDefinitionLoader';
+export * from './modules/impl/RedstoneGatewayContractDefinitionLoader';
 export * from './modules/impl/ArweaveGatewayInteractionsLoader';
 export * from './modules/impl/RedstoneGatewayInteractionsLoader';
 export * from './modules/impl/DefaultStateEvaluator';

src/core/modules/impl/ContractDefinitionLoader.ts

@@ -1,4 +1,12 @@
-import { ContractDefinition, DefinitionLoader, getTag, LoggerFactory, SmartWeaveTags, SwCache } from '@smartweave';
+import {
+  Benchmark,
+  ContractDefinition,
+  DefinitionLoader,
+  getTag,
+  LoggerFactory,
+  SmartWeaveTags,
+  SwCache
+} from '@smartweave';
 import Arweave from 'arweave';
 import Transaction from 'arweave/web/lib/transaction';
 
@@ -8,31 +16,41 @@ export class ContractDefinitionLoader implements DefinitionLoader {
   constructor(
     private readonly arweave: Arweave,
     // TODO: cache should be removed from the core layer and implemented in a wrapper of the core implementation
-    private readonly cache?: SwCache<string, ContractDefinition<unknown>>
+    protected readonly cache?: SwCache<string, ContractDefinition<unknown>>
   ) {}
 
   async load<State>(contractTxId: string, forcedSrcTxId?: string): Promise<ContractDefinition<State>> {
     if (!forcedSrcTxId && this.cache?.contains(contractTxId)) {
       this.logger.debug('ContractDefinitionLoader: Hit from cache!');
       return Promise.resolve(this.cache?.get(contractTxId) as ContractDefinition<State>);
     }
-
+    const benchmark = Benchmark.measure();
     const contract = await this.doLoad<State>(contractTxId, forcedSrcTxId);
+    this.logger.info(`Contract definition loaded in: ${benchmark.elapsed()}`);
     this.cache?.put(contractTxId, contract);
 
     return contract;
   }
 
   async doLoad<State>(contractTxId: string, forcedSrcTxId?: string): Promise<ContractDefinition<State>> {
+    const benchmark = Benchmark.measure();
     const contractTx = await this.arweave.transactions.get(contractTxId);
     const owner = await this.arweave.wallets.ownerToAddress(contractTx.owner);
+    this.logger.debug('Contract tx and owner', benchmark.elapsed());
+    benchmark.reset();
 
     const contractSrcTxId = forcedSrcTxId ? forcedSrcTxId : getTag(contractTx, SmartWeaveTags.CONTRACT_SRC_TX_ID);
-
     const minFee = getTag(contractTx, SmartWeaveTags.MIN_FEE);
+    this.logger.debug('Tags decoding', benchmark.elapsed());
+    benchmark.reset();
+
     const contractSrcTx = await this.arweave.transactions.get(contractSrcTxId);
+    this.logger.debug('Contract src tx load', benchmark.elapsed());
+    benchmark.reset();
+
     const src = contractSrcTx.get('data', { decode: true, string: true });
     const initState = JSON.parse(await this.evalInitialState(contractTx));
+    this.logger.debug('Parsing src and init state', benchmark.elapsed());
 
     return {
       txId: contractTxId,

src/core/modules/impl/ContractHandlerApi.ts

@@ -16,6 +16,7 @@ import {
 } from '@smartweave';
 import BigNumber from 'bignumber.js';
 import * as clarity from '@weavery/clarity';
+import * as v8 from 'v8';
 
 export class ContractHandlerApi<State> implements HandlerApi<State> {
   private readonly contractLogger: RedStoneLogger;
@@ -63,11 +64,7 @@ export class ContractHandlerApi<State> implements HandlerApi<State> {
       this.assignWrite(executionContext, currentTx);
       this.assignRefreshState(executionContext);
 
-      // strangely - state is for some reason modified for some contracts (eg. YLVpmhSq5JmLltfg6R-5fL04rIRPrlSU22f6RQ6VyYE)
-      // when calling any async (even simple timeout) function here...
-      // that's (ie. deepCopy) a dumb workaround for this issue
-      // see https://github.com/ArweaveTeam/SmartWeave/pull/92 for more details
-      const handlerResult = deepCopy(await Promise.race([timeoutPromise, handler(stateCopy, interaction)]));
+      const handlerResult = await Promise.race([timeoutPromise, handler(stateCopy, interaction)]);
 
       if (handlerResult && (handlerResult.state || handlerResult.result)) {
         return {