Add metrics for GQL query duration (#516)

* Record GQL query durations by operation name

* Use try finally for timer metric

* Export watcher repo URL in metrics

* Remove unnecessary prefix from repo link

* Update repository label name

---------

Co-authored-by: Prathamesh Musale <prathamesh.musale0@gmail.com>

packages/codegen/src/templates/package-template.handlebars

@@ -31,7 +31,7 @@
   },
   "repository": {
     "type": "git",
-    "url": "git+https://github.com/cerc-io/watcher-ts.git"
+    "url": "https://github.com/cerc-io/watcher-ts.git"
   },
   "author": "",
   "license": "AGPL-3.0",

packages/codegen/src/templates/resolvers-template.handlebars

@@ -12,6 +12,7 @@ import {
   {{/if}}
   gqlTotalQueryCount,
   gqlQueryCount,
+  gqlQueryDuration,
   getResultState,
   IndexerInterface,
   GraphQLBigInt,
@@ -36,6 +37,20 @@ import { {{query.entityName}} } from './entity/{{query.entityName}}';
 
 const log = debug('vulcanize:resolver');
 
+const executeAndRecordMetrics = async (gqlLabel: string, operation: () => Promise<any>) => {
+  gqlTotalQueryCount.inc(1);
+  gqlQueryCount.labels(gqlLabel).inc(1);
+  const endTimer = gqlQueryDuration.labels(gqlLabel).startTimer();
+
+  try {
+    const result = await operation();
+
+    return result;
+  } finally {
+    endTimer();
+  }
+};
+
 export const createResolvers = async (indexerArg: IndexerInterface, eventWatcher: EventWatcher): Promise<any> => {
   const indexer = indexerArg as Indexer;
 
@@ -84,14 +99,15 @@ export const createResolvers = async (indexerArg: IndexerInterface, eventWatcher
       ): Promise<ValueResult> => {
         log('{{this.name}}', blockHash, contractAddress
         {{~#each this.params}}, {{this.name~}} {{/each}});
-        gqlTotalQueryCount.inc(1);
+        
-        gqlQueryCount.labels('{{this.name}}').inc(1);
-
         // Set cache-control hints
         // setGQLCacheHints(info, {}, gqlCacheConfig);
 
-        return indexer.{{this.name}}(blockHash, contractAddress
+        return executeAndRecordMetrics(
-        {{~#each this.params}}, {{this.name~}} {{/each}});
+          '{{this.name}}',
+          async () => indexer.{{this.name}}(blockHash, contractAddress
+        {{~#each this.params}}, {{this.name~}} {{/each}})
+        );
       },
 
       {{/each}}
@@ -104,13 +120,14 @@ export const createResolvers = async (indexerArg: IndexerInterface, eventWatcher
         info: GraphQLResolveInfo
       ) => {
         log('{{this.queryName}}', id, JSON.stringify(block, jsonBigIntStringReplacer));
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('{{this.queryName}}').inc(1);
 
         // Set cache-control hints
         // setGQLCacheHints(info, block, gqlCacheConfig);
 
-        return indexer.getSubgraphEntity({{this.entityName}}, id, block, info);
+        return executeAndRecordMetrics(
+          '{{this.queryName}}',
+          async () => indexer.getSubgraphEntity({{this.entityName}}, id, block, info)
+        );
       },
 
       {{this.pluralQueryName}}: async (
@@ -120,73 +137,86 @@ export const createResolvers = async (indexerArg: IndexerInterface, eventWatcher
         info: GraphQLResolveInfo
       ) => {
         log('{{this.pluralQueryName}}', JSON.stringify(block, jsonBigIntStringReplacer), JSON.stringify(where, jsonBigIntStringReplacer), first, skip, orderBy, orderDirection);
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('{{this.pluralQueryName}}').inc(1);
 
         // Set cache-control hints
         // setGQLCacheHints(info, block, gqlCacheConfig);
 
-        return indexer.getSubgraphEntities(
+        return executeAndRecordMetrics(
-          {{this.entityName}},
+          '{{this.pluralQueryName}}',
-          block,
+          async () => indexer.getSubgraphEntities(
-          where,
+            {{this.entityName}},
-          { limit: first, skip, orderBy, orderDirection },
+            block,
-          info
+            where,
+            { limit: first, skip, orderBy, orderDirection },
+            info
+          )
         );
       },
 
       {{/each}}
       events: async (_: any, { blockHash, contractAddress, name }: { blockHash: string, contractAddress: string, name?: string }) => {
         log('events', blockHash, contractAddress, name);
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('events').inc(1);
 
-        const block = await indexer.getBlockProgress(blockHash);
+        return executeAndRecordMetrics(
-        if (!block || !block.isComplete) {
+          'events',
-          throw new Error(`Block hash ${blockHash} number ${block?.blockNumber} not processed yet`);
+          async () => {
-        }
+            const block = await indexer.getBlockProgress(blockHash);
+            if (!block || !block.isComplete) {
+              throw new Error(`Block hash ${blockHash} number ${block?.blockNumber} not processed yet`);
+            }
 
-        const events = await indexer.getEventsByFilter(blockHash, contractAddress, name);
+            const events = await indexer.getEventsByFilter(blockHash, contractAddress, name);
-        return events.map(event => indexer.getResultEvent(event));
+            return events.map(event => indexer.getResultEvent(event));
+          }
+        );
       },
 
       eventsInRange: async (_: any, { fromBlockNumber, toBlockNumber }: { fromBlockNumber: number, toBlockNumber: number }) => {
         log('eventsInRange', fromBlockNumber, toBlockNumber);
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('eventsInRange').inc(1);
 
-        const syncStatus = await indexer.getSyncStatus();
+        return executeAndRecordMetrics(
+          'eventsInRange',
+          async () => {
+            const syncStatus = await indexer.getSyncStatus();
 
-        if (!syncStatus) {
+            if (!syncStatus) {
-          throw new Error('No blocks processed yet');
+              throw new Error('No blocks processed yet');
-        }
+            }
 
-        if ((fromBlockNumber < syncStatus.initialIndexedBlockNumber) || (toBlockNumber > syncStatus.latestProcessedBlockNumber)) {
+            if ((fromBlockNumber < syncStatus.initialIndexedBlockNumber) || (toBlockNumber > syncStatus.latestProcessedBlockNumber)) {
-          throw new Error(`Block range should be between ${syncStatus.initialIndexedBlockNumber} and ${syncStatus.latestProcessedBlockNumber}`);
+              throw new Error(`Block range should be between ${syncStatus.initialIndexedBlockNumber} and ${syncStatus.latestProcessedBlockNumber}`);
-        }
+            }
 
-        const events = await indexer.getEventsInRange(fromBlockNumber, toBlockNumber);
+            const events = await indexer.getEventsInRange(fromBlockNumber, toBlockNumber);
-        return events.map(event => indexer.getResultEvent(event));
+            return events.map(event => indexer.getResultEvent(event));
+          }
+        );
       },
 
       getStateByCID: async (_: any, { cid }: { cid: string }) => {
         log('getStateByCID', cid);
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('getStateByCID').inc(1);
 
-        const state = await indexer.getStateByCID(cid);
+        return executeAndRecordMetrics(
+          'getStateByCID',
+          async () => {
+            const state = await indexer.getStateByCID(cid);
 
-        return state && state.block.isComplete ? getResultState(state) : undefined;
+            return state && state.block.isComplete ? getResultState(state) : undefined;
+          }
+        );
       },
 
       getState: async (_: any, { blockHash, contractAddress, kind }: { blockHash: string, contractAddress: string, kind: string }) => {
         log('getState', blockHash, contractAddress, kind);
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('getState').inc(1);
 
-        const state = await indexer.getPrevState(blockHash, contractAddress, kind);
+        return executeAndRecordMetrics(
+          'getState',
+          async () => {
+            const state = await indexer.getPrevState(blockHash, contractAddress, kind);
 
-        return state && state.block.isComplete ? getResultState(state) : undefined;
+            return state && state.block.isComplete ? getResultState(state) : undefined;
+          }
+        );
       },
       {{#if (subgraphPath)}}
 
@@ -195,19 +225,21 @@ export const createResolvers = async (indexerArg: IndexerInterface, eventWatcher
         { block = {} }: { block: BlockHeight }
       ) => {
         log('_meta');
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('_meta').inc(1);
 
-        return indexer.getMetaData(block);
+        return executeAndRecordMetrics(
+          '_meta',
+          async () => indexer.getMetaData(block)
+        );
       },
       {{/if}}
 
       getSyncStatus: async () => {
         log('getSyncStatus');
-        gqlTotalQueryCount.inc(1);
-        gqlQueryCount.labels('getSyncStatus').inc(1);
 
-        return indexer.getSyncStatus();
+        return executeAndRecordMetrics(
+          'getSyncStatus',
+          async () => indexer.getSyncStatus()
+        );
       }
     }
   };

packages/util/src/gql-metrics.ts

@@ -27,6 +27,13 @@ export const gqlQueryCount = new client.Counter({
   registers: [gqlRegistry]
 });
 
+export const gqlQueryDuration = new client.Gauge({
+  name: 'gql_query_duration_seconds',
+  help: 'Duration of GQL queries',
+  labelNames: ['name'] as const,
+  registers: [gqlRegistry]
+});
+
 // Export metrics on a server
 const app: Application = express();
 

packages/util/src/metrics.ts

@@ -288,8 +288,12 @@ const registerWatcherInfoMetrics = async (): Promise<void> => {
   const watcherInfoMetric = new client.Gauge({
     name: 'watcher_info',
     help: 'Watcher info (static)',
-    labelNames: ['version', 'commitHash']
+    labelNames: ['repository', 'version', 'commitHash']
   });
 
-  watcherInfoMetric.set({ version: pkgJson.version, commitHash: pkgJson.commitHash }, 1);
+  watcherInfoMetric.set({
+    repository: pkgJson.repository && pkgJson.repository.url.replace(/^git\+/, ''),
+    version: pkgJson.version,
+    commitHash: pkgJson.commitHash
+  }, 1);
 };