Merge pull request #48 from biothings/fix-425

Sub-query time elapsed logging
biothings · Mar 15, 2022 · 78e9c27 · 78e9c27
2 parents 74e8a1f + c878a92
commit 78e9c27
Showing 1 changed file with 27 additions and 13 deletions.
diff --git a/src/query.js b/src/query.js
@@ -6,6 +6,7 @@ const resolver = require("biomedical_id_resolver");
 const debug = require("debug")("bte:call-apis:query");
 const LogEntry = require("./log_entry");
 const { ResolvableBioEntity } = require("biomedical_id_resolver/built/bioentity/valid_bioentity");
+const { performance } = require('perf_hooks');
 
 
 async function delay_here(sec) {
@@ -70,22 +71,35 @@ module.exports = class APIQueryDispatcher {
                     debug("delay 1s for RTX KG2 KP...");
                     await delay_here(1);
                 }
+                const startTime = performance.now();
                 const queryResponse = dryrun_only ? {data: []} : await axios(query_config);
+                debug('query success, transforming hits->records...');
+                const finishTime = performance.now();
+                const timeElapsed = Math.round(
+                    finishTime - startTime > 1000
+                        ? (finishTime - startTime) / 1000
+                        : finishTime - startTime
+                );
+                const timeUnits = finishTime - startTime > 1000 ? "s" : "ms";
                 const unTransformedHits = {
                     response: queryResponse.data,
                     edge: query.APIEdge,
                 };
+                const tf_obj = new tf.Transformer(unTransformedHits);
+                const transformedRecords = await tf_obj.transform();
                 if (query.needPagination(unTransformedHits.response)) {
                     this.logs.push(new LogEntry("DEBUG", null, "call-apis: This query needs to be paginated").getLog());
                     debug("This query needs to be paginated");
                 }
                 // const console_msg = `Succesfully made the following query: ${JSON.stringify(query_config)}`;
-                const log_msg =  `call-apis: Successful ${query_config.method.toUpperCase()} ${query.APIEdge.query_operation.server} (${n_inputs} ID${n_inputs > 1 ? 's' : ''}): ${edge_operation}`
+                const log_msg = `call-apis: Successful ${query_config.method.toUpperCase()} ${
+                  query.APIEdge.query_operation.server
+                } (${n_inputs} ID${n_inputs > 1 ? "s" : ""}): ${edge_operation} (obtained ${
+                  transformedRecords.length
+                } record${transformedRecords.length === 1 ? "" : "s"}, took ${timeElapsed}${timeUnits})`;
                 // if (log_msg.length > 1000) {
                 //     log_msg = log_msg.substring(0, 1000) + "...";
                 // }
-                const tf_obj = new tf.Transformer(unTransformedHits);
-                const transformedRecords = await tf_obj.transform();
                 debug(log_msg);
                 this.logs.push(
                     new LogEntry(
@@ -99,14 +113,6 @@ module.exports = class APIQueryDispatcher {
                         }
                     ).getLog(),
                 );
-                debug(`After transformation, BTE is able to retrieve ${transformedRecords.length} records!`);
-                this.logs.push(
-                    new LogEntry(
-                        "DEBUG",
-                        null,
-                        `call-apis: After transformation, BTE is able to retrieve ${transformedRecords.length} records!`,
-                    ).getLog(),
-                );
                 return transformedRecords;
             } catch (error) {
                 if ((error.response && error.response.status >= 502) || error.code === 'ECONNABORTED') {
@@ -177,19 +183,27 @@ module.exports = class APIQueryDispatcher {
         let queryRecords = [];
         const queries = this._constructQueries(this.APIEdges);
         this._constructQueue(queries);
+        const startTime = performance.now();
         while (this.queue.queue.length > 0) {
             const bucket = this.queue.queue[0].getBucket();
             let newHits = await this._queryBucket(bucket, unavailableAPIs);
             queryRecords = [...queryRecords, ...newHits];
             this._checkIfNext(bucket);
         }
+        const finishTime = performance.now();
+        const timeElapsed = Math.round(
+            finishTime - startTime > 1000
+                ? (finishTime - startTime) / 1000
+                : finishTime - startTime
+        );
+        const timeUnits = finishTime - startTime > 1000 ? "s" : "ms";
         debug("query completes.")
         const mergedRecords = this._merge(queryRecords);
         debug("Start to use id resolver module to annotate output ids.")
         const annotatedRecords = await this._annotate(mergedRecords, resolveOutputIDs);
         debug("id annotation completes");
-        debug("Query completes");
-        this.logs.push(new LogEntry("DEBUG", null, "call-apis: Query completes").getLog());
+        debug(`qEdge queries complete in ${timeElapsed}${timeUnits}`);
+        this.logs.push(new LogEntry("DEBUG", null, `call-apis: qEdge queries complete in ${timeElapsed}${timeUnits}`).getLog());
         return annotatedRecords;
     }