>From Peeyush Gupta <[email protected]>: Peeyush Gupta has submitted this change. ( https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/17854 )
Change subject: [ASTERIXDB-3277][API] Adding query queue time to stats data. ...................................................................... [ASTERIXDB-3277][API] Adding query queue time to stats data. - user model changes: yes - storage format changes: no - interface changes: no Details: Adding query waiting time inside job queue as a part of returned metric. -added queueWaitTime inside stats. -adding queueWaitTime inside metric and reading it from stats. Change-Id: I1ff41693e7080abe5535c402d0dbb6b8bc387a37 Reviewed-on: https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/17854 Integration-Tests: Jenkins <[email protected]> Tested-by: Jenkins <[email protected]> Reviewed-by: Peeyush Gupta <[email protected]> --- M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.04.regexadm M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.07.regexadm M asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/fields/MetricsPrinter.java M asterixdb/asterix-algebra/src/main/java/org/apache/asterix/translator/IStatementExecutor.java M asterixdb/asterix-app/src/main/java/org/apache/asterix/app/translator/QueryTranslator.java M asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java M asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.05.regexadm M asterixdb/asterix-app/src/test/resources/runtimets/results/api/request-param-validation-400-BAD/request-param-validation-400-BAD.01.regexjson M hyracks-fullstack/hyracks/hyracks-control/hyracks-control-common/src/main/java/org/apache/hyracks/control/common/job/profiling/om/JobProfile.java M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.08.regexadm M asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryResultApiServlet.java M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.06.regexadm M asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/ResponseMetrics.java M asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.03.regexadm 15 files changed, 62 insertions(+), 3 deletions(-) Approvals: Peeyush Gupta: Looks good to me, approved Jenkins: Verified; Verified Objections: Anon. E. Moose #1000171: Violations found diff --git a/asterixdb/asterix-algebra/src/main/java/org/apache/asterix/translator/IStatementExecutor.java b/asterixdb/asterix-algebra/src/main/java/org/apache/asterix/translator/IStatementExecutor.java index b47d45d..e10046e 100644 --- a/asterixdb/asterix-algebra/src/main/java/org/apache/asterix/translator/IStatementExecutor.java +++ b/asterixdb/asterix-algebra/src/main/java/org/apache/asterix/translator/IStatementExecutor.java @@ -133,6 +133,7 @@ private long count; private long size; private long processedObjects; + private long queueWaitTime; private Profile profile; private ProfileType profileType; private long totalWarningsCount; @@ -154,6 +155,10 @@ this.size = size; } + public long getQueueWaitTime() { + return queueWaitTime; + } + public long getProcessedObjects() { return processedObjects; } @@ -172,6 +177,10 @@ } } + public void setQueueWaitTime(long queueWaitTime) { + this.queueWaitTime = queueWaitTime; + } + public void setJobProfile(ObjectNode profile) { this.profile = new Profile(profile); } diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java index 695956c..cb5a3a5 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java @@ -206,6 +206,7 @@ stats.setProcessedObjects(responseStats.getProcessedObjects()); stats.updateTotalWarningsCount(responseStats.getTotalWarningsCount()); stats.setCompileTime(responseStats.getCompileTime()); + stats.setQueueWaitTime(responseStats.getQueueWaitTime()); } private static void updatePropertiesFromCC(IStatementExecutor.StatementProperties statementProperties, diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryResultApiServlet.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryResultApiServlet.java index d9df051..680feeb 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryResultApiServlet.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryResultApiServlet.java @@ -102,7 +102,7 @@ printer.printResults(); ResponseMetrics metrics = ResponseMetrics.of(System.nanoTime() - elapsedStart, metadata.getJobDuration(), stats.getCount(), stats.getSize(), metadata.getProcessedObjects(), 0, - metadata.getTotalWarningsCount(), stats.getCompileTime()); + metadata.getTotalWarningsCount(), stats.getCompileTime(), stats.getQueueWaitTime()); printer.addFooterPrinter(new MetricsPrinter(metrics, HttpUtil.getPreferredCharset(request))); if (metadata.getJobProfile() != null) { printer.addFooterPrinter(new ProfilePrinter(metadata.getJobProfile())); diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java index e14c185..6678c52 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceServlet.java @@ -359,7 +359,7 @@ } final ResponseMetrics metrics = ResponseMetrics.of(System.nanoTime() - elapsedStart, executionState.duration(), stats.getCount(), stats.getSize(), stats.getProcessedObjects(), errorCount, - stats.getTotalWarningsCount(), stats.getCompileTime()); + stats.getTotalWarningsCount(), stats.getCompileTime(), stats.getQueueWaitTime()); responsePrinter.addFooterPrinter(new MetricsPrinter(metrics, resultCharset)); if (isPrintingProfile(stats)) { responsePrinter.addFooterPrinter(new ProfilePrinter(stats.getJobProfile())); diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/ResponseMetrics.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/ResponseMetrics.java index d55bb07..08e7702 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/ResponseMetrics.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/ResponseMetrics.java @@ -29,12 +29,13 @@ private long warnCount; private long diskIoCount; private long compileTime; + private long queueWaitTime; private ResponseMetrics() { } public static ResponseMetrics of(long elapsedTime, long executionTime, long resultCount, long resultSize, - long processedObjects, long errorCount, long warnCount, long compileTime) { + long processedObjects, long errorCount, long warnCount, long compileTime, long queueWaitTime) { ResponseMetrics metrics = new ResponseMetrics(); metrics.elapsedTime = elapsedTime; metrics.executionTime = executionTime; @@ -44,6 +45,7 @@ metrics.errorCount = errorCount; metrics.warnCount = warnCount; metrics.compileTime = compileTime; + metrics.queueWaitTime = queueWaitTime; return metrics; } @@ -78,4 +80,8 @@ public long getCompileTime() { return compileTime; } + + public long getQueueWaitTime() { + return queueWaitTime; + } } diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/fields/MetricsPrinter.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/fields/MetricsPrinter.java index 6b1d670..e001d29 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/fields/MetricsPrinter.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/result/fields/MetricsPrinter.java @@ -33,6 +33,7 @@ ELAPSED_TIME("elapsedTime"), EXECUTION_TIME("executionTime"), COMPILE_TIME("compileTime"), + QUEUE_WAIT_TIME("queueWaitTime"), RESULT_COUNT("resultCount"), RESULT_SIZE("resultSize"), ERROR_COUNT("errorCount"), @@ -74,6 +75,9 @@ pw.print("\n\t"); ResultUtil.printField(pw, Metrics.COMPILE_TIME.str(), Duration.formatNanos(metrics.getCompileTime(), useAscii)); pw.print("\n\t"); + ResultUtil.printField(pw, Metrics.QUEUE_WAIT_TIME.str(), + Duration.formatNanos(metrics.getQueueWaitTime(), useAscii)); + pw.print("\n\t"); ResultUtil.printField(pw, Metrics.RESULT_COUNT.str(), metrics.getResultCount(), true); pw.print("\n\t"); ResultUtil.printField(pw, Metrics.RESULT_SIZE.str(), metrics.getResultSize(), true); diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/translator/QueryTranslator.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/translator/QueryTranslator.java index cb64c01..fc539ef 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/translator/QueryTranslator.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/app/translator/QueryTranslator.java @@ -4778,6 +4778,10 @@ (org.apache.asterix.translator.ResultMetadata) controllerService.getResultDirectoryService() .getResultMetadata(jobId, rsId); stats.setProcessedObjects(resultMetadata.getProcessedObjects()); + if (controllerService.getJobManager().get(jobId) != null) { + stats.setQueueWaitTime( + controllerService.getJobManager().get(jobId).getJobProfile().getQueueWaitTimeInNanos()); + } if (jobFlags.contains(JobFlag.PROFILE_RUNTIME)) { stats.setJobProfile(resultMetadata.getJobProfile()); apiFramework.generateOptimizedLogicalPlanWithProfile(resultMetadata.getJobProfile()); diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/api/request-param-validation-400-BAD/request-param-validation-400-BAD.01.regexjson b/asterixdb/asterix-app/src/test/resources/runtimets/results/api/request-param-validation-400-BAD/request-param-validation-400-BAD.01.regexjson index 6fa99e2..bd58b52 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/api/request-param-validation-400-BAD/request-param-validation-400-BAD.01.regexjson +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/api/request-param-validation-400-BAD/request-param-validation-400-BAD.01.regexjson @@ -7,6 +7,7 @@ "elapsedTime": "R{.*}", "executionTime": "R{.*}", "compileTime": "R{.*}", + "queueWaitTime": "R{.*}", "resultCount": 0, "resultSize": 0, "processedObjects": 0, diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.03.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.03.regexadm index 7029ce2..bd85d0e 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.03.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.03.regexadm @@ -32,6 +32,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.04.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.04.regexadm index 8478d17..dce84fe 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.04.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.04.regexadm @@ -25,6 +25,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.05.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.05.regexadm index 5399ed8..6b1931a 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.05.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.05.regexadm @@ -25,6 +25,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.06.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.06.regexadm index aa58fb4..7b689f6 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.06.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.06.regexadm @@ -13,6 +13,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.07.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.07.regexadm index 5399ed8..6b1931a 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.07.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.07.regexadm @@ -25,6 +25,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.08.regexadm b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.08.regexadm index 7029ce2..bd85d0e 100644 --- a/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.08.regexadm +++ b/asterixdb/asterix-app/src/test/resources/runtimets/results/warnings/warnings-limit/warnings-limit.08.regexadm @@ -32,6 +32,7 @@ \s*\Q"elapsedTime": "\E[^"]+\Q",\E \s*\Q"executionTime": "\E[^"]+\Q",\E \s*\Q"compileTime": "\E[^"]+\Q",\E +\s*\Q"queueWaitTime": "\E[^"]+\Q",\E \s*\Q"resultCount": \E[0-9]+\Q,\E \s*\Q"resultSize": \E[0-9]+\Q,\E \s*\Q"processedObjects": \E[0-9]+\Q,\E diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-common/src/main/java/org/apache/hyracks/control/common/job/profiling/om/JobProfile.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-common/src/main/java/org/apache/hyracks/control/common/job/profiling/om/JobProfile.java index f4cd4d6..871d2bc 100644 --- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-common/src/main/java/org/apache/hyracks/control/common/job/profiling/om/JobProfile.java +++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-common/src/main/java/org/apache/hyracks/control/common/job/profiling/om/JobProfile.java @@ -26,6 +26,7 @@ import java.util.List; import java.util.Map; import java.util.Map.Entry; +import java.util.concurrent.TimeUnit; import org.apache.hyracks.api.dataflow.TaskAttemptId; import org.apache.hyracks.api.dataflow.TaskId; @@ -89,6 +90,10 @@ this.endTime = endTime; } + public long getQueueWaitTimeInNanos() { + return TimeUnit.MILLISECONDS.toNanos(startTime - createTime); + } + @Override public ObjectNode toJSON() { ObjectMapper om = new ObjectMapper(); -- To view, visit https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/17854 To unsubscribe, or for help writing mail filters, visit https://asterix-gerrit.ics.uci.edu/settings Gerrit-Project: asterixdb Gerrit-Branch: trinity Gerrit-Change-Id: I1ff41693e7080abe5535c402d0dbb6b8bc387a37 Gerrit-Change-Number: 17854 Gerrit-PatchSet: 24 Gerrit-Owner: Ayush Tripathi <[email protected]> Gerrit-Reviewer: Anon. E. Moose #1000171 Gerrit-Reviewer: Jenkins <[email protected]> Gerrit-Reviewer: Peeyush Gupta <[email protected]> Gerrit-CC: Michael Blow <[email protected]> Gerrit-CC: Murtadha Hubail <[email protected]> Gerrit-MessageType: merged
