Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Sub-query time elapsed logging #48

Merged
merged 3 commits into from
Mar 15, 2022
+27 −13
Merged

Sub-query time elapsed logging #48

Changes from all commits
Commits
Show all changes
3 commits
Select commit Hold shift + click to select a range
23ce315
feat: sub-query time logs
tokebe Mar 14, 2022
7a4220c
fix: log plurals
tokebe Mar 14, 2022
c878a92
fix: explicit import performance
tokebe Mar 15, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
40 changes: 27 additions & 13 deletions src/query.js
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -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) {
Expand Down Expand Up @@ -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(
Expand All @@ -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') {
Expand Down Expand Up @@ -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;
}

Expand Down