Add time logs for uniswap watchers (#310)

* Log time taken in watchers

* Log time for all events and for each event batch

Co-authored-by: prathamesh0 <prathamesh@deepstacksoft.com>

packages/uni-info-watcher/src/indexer.ts

@@ -90,6 +90,7 @@ export class Indexer implements IndexerInterface {
   }
 
   async processEvent (dbEvent: Event): Promise<void> {
+    console.time('time:indexer#processEvent-mapping_code');
     const resultEvent = this.getResultEvent(dbEvent);
 
     // TODO: Process proof (proof.data) in event.
@@ -148,6 +149,7 @@ export class Indexer implements IndexerInterface {
     }
 
     log('Event processing completed for', eventName);
+    console.timeEnd('time:indexer#processEvent-mapping_code');
   }
 
   async getBlockEntities (where: { [key: string]: any } = {}, queryOptions: QueryOptions): Promise<any> {
@@ -360,7 +362,11 @@ export class Indexer implements IndexerInterface {
 
   async _fetchAndSaveEvents (block: DeepPartial<BlockProgress>): Promise<BlockProgress> {
     assert(block.blockHash);
+
+    console.time('time:indexer#_fetchAndSaveEvents-uni_watcher');
     const events = await this._uniClient.getEvents(block.blockHash);
+    console.timeEnd('time:indexer#_fetchAndSaveEvents-uni_watcher');
+
     const dbEvents: Array<DeepPartial<Event>> = [];
 
     for (let i = 0; i < events.length; i++) {
@@ -501,10 +507,20 @@ export class Indexer implements IndexerInterface {
     const token = new Token();
     token.id = tokenAddress;
 
-    const { value: symbol } = await this._erc20Client.getSymbol(block.hash, tokenAddress);
+    console.time('time:indexer#_initToken-eth_call_for_token');
-    const { value: name } = await this._erc20Client.getName(block.hash, tokenAddress);
+    const symbolPromise = this._erc20Client.getSymbol(block.hash, tokenAddress);
-    const { value: totalSupply } = await this._erc20Client.getTotalSupply(block.hash, tokenAddress);
+    const namePromise = this._erc20Client.getName(block.hash, tokenAddress);
-    const { value: decimals } = await this._erc20Client.getDecimals(block.hash, tokenAddress);
+    const totalSupplyPromise = this._erc20Client.getTotalSupply(block.hash, tokenAddress);
+    const decimalsPromise = this._erc20Client.getDecimals(block.hash, tokenAddress);
+
+    const [
+      { value: symbol },
+      { value: name },
+      { value: totalSupply },
+      { value: decimals }
+    ] = await Promise.all([symbolPromise, namePromise, totalSupplyPromise, decimalsPromise]);
+
+    console.timeEnd('time:indexer#_initToken-eth_call_for_token');
 
     token.symbol = symbol;
     token.name = name;
@@ -1311,7 +1327,9 @@ export class Indexer implements IndexerInterface {
       let positionResult;
 
       try {
+        console.time('time:indexer#_getPosition-eth_call_for_positions');
         ({ value: positionResult } = await this._uniClient.positions(blockHash, contractAddress, tokenId));
+        console.timeEnd('time:indexer#_getPosition-eth_call_for_positions');
       } catch (error: any) {
         // The contract call reverts in situations where the position is minted and deleted in the same block.
         // From my investigation this happens in calls from BancorSwap.
@@ -1327,7 +1345,10 @@ export class Indexer implements IndexerInterface {
         // TODO: In subgraph factory is fetched by hardcoded factory address.
         // Currently fetching first factory in database as only one exists.
         const [factory] = await this._db.getModelEntitiesNoTx(Factory, { hash: blockHash }, {}, { limit: 1 });
+
+        console.time('time:indexer#_getPosition-eth_call_for_getPool');
         const { value: poolAddress } = await this._uniClient.callGetPool(blockHash, factory.id, positionResult.token0, positionResult.token1, positionResult.fee);
+        console.timeEnd('time:indexer#_getPosition-eth_call_for_getPool');
 
         position = new Position();
         position.id = tokenId.toString();
@@ -1362,7 +1383,9 @@ export class Indexer implements IndexerInterface {
 
   async _updateFeeVars (position: Position, block: Block, contractAddress: string, tokenId: bigint): Promise<Position> {
     try {
+      console.time('time:indexer#_updateFeeVars-eth_call_for_positions');
       const { value: positionResult } = await this._uniClient.positions(block.hash, contractAddress, tokenId);
+      console.timeEnd('time:indexer#_updateFeeVars-eth_call_for_positions');
 
       if (positionResult) {
         position.feeGrowthInside0LastX128 = BigInt(positionResult.feeGrowthInside0LastX128.toString());

packages/uni-watcher/src/indexer.ts

@@ -431,6 +431,7 @@ export class Indexer implements IndexerInterface {
   async _fetchAndSaveEvents ({ blockHash }: DeepPartial<BlockProgress>): Promise<BlockProgress> {
     assert(blockHash);
 
+    console.time('time:indexer#_fetchAndSaveEvents-logs_txs');
     const logsPromise = this._ethClient.getLogs({ blockHash });
     const transactionsPromise = this._postgraphileClient.getBlockWithTransactions({ blockHash });
 
@@ -449,6 +450,8 @@ export class Indexer implements IndexerInterface {
       }
     ] = await Promise.all([logsPromise, transactionsPromise]);
 
+    console.timeEnd('time:indexer#_fetchAndSaveEvents-logs_txs');
+
     const transactionMap = transactions.reduce((acc: {[key: string]: any}, transaction: {[key: string]: any}) => {
       acc[transaction.txHash] = transaction;
       return acc;

packages/util/src/common.ts

@@ -47,8 +47,12 @@ export const processBlockByNumber = async (
   log(`Process block ${blockNumber}`);
 
   while (true) {
+    console.time('time:common#processBlockByNumber-postgraphile');
+
     const blocks = await indexer.getBlocks({ blockNumber });
 
+    console.timeEnd('time:common#processBlockByNumber-postgraphile');
+
     if (blocks.length) {
       for (let bi = 0; bi < blocks.length; bi++) {
         const { blockHash, blockNumber, parentHash, timestamp } = blocks[bi];

packages/util/src/fill.ts

@@ -34,6 +34,8 @@ export const fillBlocks = async (
     currentBlockNumber = syncStatus.latestIndexedBlockNumber + 1;
   }
 
+  console.time(`time:fill#fillBlocks-process_block_${currentBlockNumber}`);
+
   processBlockByNumber(jobQueue, indexer, blockDelayInMilliSecs, currentBlockNumber);
 
   // Creating an AsyncIterable from AsyncIterator to iterate over the values.
@@ -43,19 +45,28 @@ export const fillBlocks = async (
     [Symbol.asyncIterator]: eventWatcher.getBlockProgressEventIterator.bind(eventWatcher)
   };
 
+  console.time('time:fill#fillBlocks-process_blocks');
+
   // Iterate over async iterable.
   // https://developer.mozilla.org/en-US/docs/Web/JavaScript/Reference/Statements/for-await...of
   for await (const data of blockProgressEventIterable) {
     const { onBlockProgressEvent: { blockNumber, isComplete } } = data;
 
     if (blockNumber === currentBlockNumber && isComplete) {
+      console.timeEnd(`time:fill#fillBlocks-process_block_${currentBlockNumber}`);
+
       if (blockNumber >= endBlock) {
         // Break the async loop when blockProgress event is for the endBlock and processing is complete.
         break;
       }
 
       currentBlockNumber++;
+
+      console.time(`time:fill#fillBlocks-process_block_${currentBlockNumber}`);
+
       processBlockByNumber(jobQueue, indexer, blockDelayInMilliSecs, currentBlockNumber);
     }
   }
+
+  console.timeEnd('time:fill#fillBlocks-process_blocks');
 };

packages/util/src/job-runner.ts

@@ -194,7 +194,11 @@ export class JobRunner {
     let block = await this._indexer.getBlockProgress(blockHash);
     assert(block);
 
+    console.time('time:job-runner#_processEvents-events');
+
     while (!block.isComplete) {
+      console.time('time:job-runner#_processEvents-fetching_events_batch');
+
       // Fetch events in batches
       const events: EventInterface[] = await this._indexer.getBlockEvents(
         blockHash,
@@ -210,6 +214,10 @@ export class JobRunner {
         }
       );
 
+      console.timeEnd('time:job-runner#_processEvents-fetching_events_batch');
+
+      console.time('time:job-runner#_processEvents-processing_events_batch');
+
       for (let event of events) {
         // Process events in loop
 
@@ -255,7 +263,11 @@ export class JobRunner {
 
         block = await this._indexer.updateBlockProgress(block, event.index);
       }
+
+      console.timeEnd('time:job-runner#_processEvents-processing_events_batch');
     }
+
+    console.timeEnd('time:job-runner#_processEvents-events');
   }
 
   async _updateWatchedContracts (job: any): Promise<void> {