From 65f46ff69a9c237e6a4ec28b3cc745432fb1d330 Mon Sep 17 00:00:00 2001 From: Kunal Khatua Date: Sun, 29 Jan 2017 23:08:12 -0800 Subject: [PATCH] DRILL-5230: Translation of millisecond duration into hours is incorrect Fixed invalid representation of readable elapsed time using `TimeUnit` class in JDK. e.g. 4545 sec is now correctly translated as `1h15m` instead of `17h15m` --- .../server/rest/profile/FragmentWrapper.java | 14 +-- .../server/rest/profile/OperatorWrapper.java | 14 +-- .../server/rest/profile/ProfileResources.java | 38 ++---- .../server/rest/profile/ProfileWrapper.java | 2 +- .../rest/profile/SimpleDurationFormat.java | 77 ++++++++++++ .../server/rest/profile/TableBuilder.java | 36 +----- .../drill/exec/server/TestDurationFormat.java | 115 ++++++++++++++++++ 7 files changed, 217 insertions(+), 79 deletions(-) create mode 100644 exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/SimpleDurationFormat.java create mode 100644 exec/java-exec/src/test/java/org/apache/drill/exec/server/TestDurationFormat.java diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/FragmentWrapper.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/FragmentWrapper.java index 2a8b564aa94..ec0e2c80ca2 100644 --- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/FragmentWrapper.java +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/FragmentWrapper.java @@ -57,8 +57,6 @@ public String getId() { public static final int NUM_NULLABLE_OVERVIEW_COLUMNS = FRAGMENT_OVERVIEW_COLUMNS.length - 2; public void addSummary(TableBuilder tb) { - final String fmt = " (%d)"; - // Use only minor fragments that have complete profiles // Complete iff the fragment profile has at least one operator profile, and start and end times. final List complete = new ArrayList<>( @@ -75,13 +73,13 @@ public void addSummary(TableBuilder tb) { final MinorFragmentProfile firstStart = Collections.min(complete, Comparators.startTime); final MinorFragmentProfile lastStart = Collections.max(complete, Comparators.startTime); - tb.appendMillis(firstStart.getStartTime() - start, String.format(fmt, firstStart.getMinorFragmentId())); - tb.appendMillis(lastStart.getStartTime() - start, String.format(fmt, lastStart.getMinorFragmentId())); + tb.appendMillis(firstStart.getStartTime() - start, null); + tb.appendMillis(lastStart.getStartTime() - start, null); final MinorFragmentProfile firstEnd = Collections.min(complete, Comparators.endTime); final MinorFragmentProfile lastEnd = Collections.max(complete, Comparators.endTime); - tb.appendMillis(firstEnd.getEndTime() - start, String.format(fmt, firstEnd.getMinorFragmentId())); - tb.appendMillis(lastEnd.getEndTime() - start, String.format(fmt, lastEnd.getMinorFragmentId())); + tb.appendMillis(firstEnd.getEndTime() - start, null); + tb.appendMillis(lastEnd.getEndTime() - start, null); long total = 0; for (final MinorFragmentProfile p : complete) { @@ -90,9 +88,9 @@ public void addSummary(TableBuilder tb) { final MinorFragmentProfile shortRun = Collections.min(complete, Comparators.runTime); final MinorFragmentProfile longRun = Collections.max(complete, Comparators.runTime); - tb.appendMillis(shortRun.getEndTime() - shortRun.getStartTime(), String.format(fmt, shortRun.getMinorFragmentId())); + tb.appendMillis(shortRun.getEndTime() - shortRun.getStartTime(), null); tb.appendMillis(total / complete.size(), null); - tb.appendMillis(longRun.getEndTime() - longRun.getStartTime(), String.format(fmt, longRun.getMinorFragmentId())); + tb.appendMillis(longRun.getEndTime() - longRun.getStartTime(), null); final MinorFragmentProfile lastUpdate = Collections.max(complete, Comparators.lastUpdate); tb.appendTime(lastUpdate.getLastUpdate(), null); diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/OperatorWrapper.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/OperatorWrapper.java index 4cc79710779..19266556296 100644 --- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/OperatorWrapper.java +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/OperatorWrapper.java @@ -32,8 +32,6 @@ * Wrapper class for profiles of ALL operator instances of the same operator type within a major fragment. */ public class OperatorWrapper { - private static final String format = " (%s)"; - private final int major; private final List> ops; // operator profile --> minor fragment number private final OperatorProfile firstProfile; @@ -114,21 +112,21 @@ public void addSummary(TableBuilder tb) { final ImmutablePair shortSetup = Collections.min(ops, Comparators.setupTime); final ImmutablePair longSetup = Collections.max(ops, Comparators.setupTime); - tb.appendNanos(shortSetup.getLeft().getSetupNanos(), String.format(format, shortSetup.getRight())); + tb.appendNanos(shortSetup.getLeft().getSetupNanos(), null); tb.appendNanos(Math.round(setupSum / size), null); - tb.appendNanos(longSetup.getLeft().getSetupNanos(), String.format(format, longSetup.getRight())); + tb.appendNanos(longSetup.getLeft().getSetupNanos(), null); final ImmutablePair shortProcess = Collections.min(ops, Comparators.processTime); final ImmutablePair longProcess = Collections.max(ops, Comparators.processTime); - tb.appendNanos(shortProcess.getLeft().getProcessNanos(), String.format(format, shortProcess.getRight())); + tb.appendNanos(shortProcess.getLeft().getProcessNanos(), null); tb.appendNanos(Math.round(processSum / size), null); - tb.appendNanos(longProcess.getLeft().getProcessNanos(), String.format(format, longProcess.getRight())); + tb.appendNanos(longProcess.getLeft().getProcessNanos(), null); final ImmutablePair shortWait = Collections.min(ops, Comparators.waitTime); final ImmutablePair longWait = Collections.max(ops, Comparators.waitTime); - tb.appendNanos(shortWait.getLeft().getWaitNanos(), String.format(format, shortWait.getRight())); + tb.appendNanos(shortWait.getLeft().getWaitNanos(), null); tb.appendNanos(Math.round(waitSum / size), null); - tb.appendNanos(longWait.getLeft().getWaitNanos(), String.format(format, longWait.getRight())); + tb.appendNanos(longWait.getLeft().getWaitNanos(), null); final ImmutablePair peakMem = Collections.max(ops, Comparators.operatorPeakMemory); tb.appendBytes(Math.round(memSum / size), null); diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileResources.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileResources.java index 24d37b2a8f3..9ab4f4a0570 100644 --- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileResources.java +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileResources.java @@ -68,25 +68,6 @@ public class ProfileResources { @Inject DrillUserPrincipal principal; @Inject SecurityContext sc; - /** - * Returns elapsed time a human-readable format. If end time is less than the start time, current epoch time is assumed as the end time. - * e.g. getPrettyDuration(1468368841695,1468394096016) = '7 hr 00 min 54.321 sec' - * @param startTimeMillis Start Time in milliseconds - * @param endTimeMillis End Time in milliseconds - * @return Human-Readable Elapsed Time - */ - public static String getPrettyDuration(long startTimeMillis, long endTimeMillis) { - long durationInMillis = (startTimeMillis > endTimeMillis ? System.currentTimeMillis() : endTimeMillis) - startTimeMillis; - long hours = TimeUnit.MILLISECONDS.toHours(durationInMillis); - long minutes = TimeUnit.MILLISECONDS.toMinutes(durationInMillis) - TimeUnit.HOURS.toMinutes(TimeUnit.MILLISECONDS.toHours(durationInMillis)); - long seconds = TimeUnit.MILLISECONDS.toSeconds(durationInMillis) - TimeUnit.MINUTES.toSeconds(TimeUnit.MILLISECONDS.toMinutes(durationInMillis)); - long milliSeconds = durationInMillis - TimeUnit.SECONDS.toMillis(TimeUnit.MILLISECONDS.toSeconds(durationInMillis)); - String formattedDuration = (hours > 0 ? hours + " hr " : "") + - ((minutes + hours) > 0 ? String.format("%02d min ", minutes) : "") + - seconds + "." + String.format("%03d sec", milliSeconds) ; - return formattedDuration; - } - public static class ProfileInfo implements Comparable { public static final SimpleDateFormat format = new SimpleDateFormat("MM/dd/yyyy HH:mm:ss"); @@ -137,7 +118,7 @@ public long getEndTime() { } public String getDuration() { - return getPrettyDuration(startTime, endTime); + return (new SimpleDurationFormat(startTime, endTime)).verbose(); } public String getState() { @@ -237,8 +218,8 @@ public QProfiles getProfilesJSON() { return new QProfiles(runningQueries, finishedQueries, errors); } catch (Exception e) { throw UserException.resourceError(e) - .message("Failed to get profiles from persistent or ephemeral store.") - .build(logger); + .message("Failed to get profiles from persistent or ephemeral store.") + .build(logger); } } @@ -291,8 +272,8 @@ private QueryProfile getQueryProfile(String queryId) { } throw UserException.validationError() - .message("No profile with given query id '%s' exists. Please verify the query id.", queryId) - .build(logger); + .message("No profile with given query id '%s' exists. Please verify the query id.", queryId) + .build(logger); } @@ -352,16 +333,17 @@ public String cancelQuery(@PathParam("queryid") String queryId) { private void checkOrThrowProfileViewAuthorization(final QueryProfile profile) { if (!principal.canManageProfileOf(profile.getUser())) { throw UserException.permissionError() - .message("Not authorized to view the profile of query '%s'", profile.getId()) - .build(logger); + .message("Not authorized to view the profile of query '%s'", profile.getId()) + .build(logger); } } private void checkOrThrowQueryCancelAuthorization(final String queryUser, final String queryId) { if (!principal.canManageQueryOf(queryUser)) { throw UserException.permissionError() - .message("Not authorized to cancel the query '%s'", queryId) - .build(logger); + .message("Not authorized to cancel the query '%s'", queryId) + .build(logger); } } } + diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileWrapper.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileWrapper.java index 57223f6ace9..20de752deab 100644 --- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileWrapper.java +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/ProfileWrapper.java @@ -115,7 +115,7 @@ public QueryProfile getProfile() { } public String getProfileDuration() { - return ProfileResources.getPrettyDuration(profile.getStart(), profile.getEnd()); + return (new SimpleDurationFormat(profile.getStart(), profile.getEnd())).verbose(); } public String getQueryId() { diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/SimpleDurationFormat.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/SimpleDurationFormat.java new file mode 100644 index 00000000000..00f2b665a03 --- /dev/null +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/SimpleDurationFormat.java @@ -0,0 +1,77 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.drill.exec.server.rest.profile; + +import java.util.concurrent.TimeUnit; + +/** + * Representation of a millisecond duration in a human-readable format + */ +public class SimpleDurationFormat { + private long days; + private long hours; + private long minutes; + private long seconds; + private long milliSeconds; + private long durationInMillis; + + //Block creation of any default objects + @SuppressWarnings("unused") + private SimpleDurationFormat() {} + + /** + * If end time is less than the start time, current epoch time is assumed as the end time. + * @param startTimeMillis + * @param endTimeMillis + */ + public SimpleDurationFormat(long startTimeMillis, long endTimeMillis) { + durationInMillis = (startTimeMillis > endTimeMillis ? System.currentTimeMillis() : endTimeMillis) - startTimeMillis; + days = TimeUnit.MILLISECONDS.toDays(durationInMillis); + hours = TimeUnit.MILLISECONDS.toHours(durationInMillis) - TimeUnit.DAYS.toHours(TimeUnit.MILLISECONDS.toDays(durationInMillis)); + minutes = TimeUnit.MILLISECONDS.toMinutes(durationInMillis) - TimeUnit.HOURS.toMinutes(TimeUnit.MILLISECONDS.toHours(durationInMillis)); + seconds = TimeUnit.MILLISECONDS.toSeconds(durationInMillis) - TimeUnit.MINUTES.toSeconds(TimeUnit.MILLISECONDS.toMinutes(durationInMillis)); + milliSeconds = durationInMillis - TimeUnit.SECONDS.toMillis(TimeUnit.MILLISECONDS.toSeconds(durationInMillis)); + } + + /** + * Return a compact representation of elapsed time with only the most significant time units and no spaces + * @return duration + */ + public String compact() { + if (days >= 1) { + return days + "d" + hours + "h" + minutes + "m"; + } else if (hours >= 1) { + return hours + "h" + minutes + "m"; + } else if (minutes >= 1) { + return minutes + "m" + seconds + "s"; + } else { + return String.format("%.3fs", seconds + milliSeconds/1000.0); + } + } + + /** + * Return a verbose representation of elapsed time down to millisecond granularity + * @return duration + */ + public String verbose() { + return (days > 0 ? days + " day " : "") + + ((hours + days) > 0 ? hours + " hr " : "") + + ((minutes + hours + days) > 0 ? String.format("%02d min ", minutes) : "") + + seconds + "." + String.format("%03d sec", milliSeconds) ; + } +} diff --git a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/TableBuilder.java b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/TableBuilder.java index 83557976312..7893be4b6a4 100644 --- a/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/TableBuilder.java +++ b/exec/java-exec/src/main/java/org/apache/drill/exec/server/rest/profile/TableBuilder.java @@ -21,20 +21,10 @@ import java.text.DecimalFormat; import java.text.NumberFormat; import java.text.SimpleDateFormat; -import java.util.Date; import java.util.Locale; -class TableBuilder { +public class TableBuilder { private final NumberFormat format = NumberFormat.getInstance(Locale.US); - private final SimpleDateFormat days = new SimpleDateFormat("DD'd'hh'h'mm'm'"); - private final SimpleDateFormat sdays = new SimpleDateFormat("DD'd'hh'h'mm'm'"); - private final SimpleDateFormat hours = new SimpleDateFormat("HH'h'mm'm'"); - private final SimpleDateFormat shours = new SimpleDateFormat("H'h'mm'm'"); - private final SimpleDateFormat mins = new SimpleDateFormat("mm'm'ss's'"); - private final SimpleDateFormat smins = new SimpleDateFormat("m'm'ss's'"); - - private final SimpleDateFormat secs = new SimpleDateFormat("ss.SSS's'"); - private final SimpleDateFormat ssecs = new SimpleDateFormat("s.SSS's'"); private final DateFormat dateFormat = new SimpleDateFormat("HH:mm:ss"); private final DecimalFormat dec = new DecimalFormat("0.00"); private final DecimalFormat intformat = new DecimalFormat("#,###"); @@ -78,29 +68,7 @@ public void appendTime(final long d, final String link) { } public void appendMillis(final long p, final String link) { - final double secs = p/1000.0; - final double mins = secs/60; - final double hours = mins/60; - final double days = hours / 24; - SimpleDateFormat timeFormat = null; - if (days >= 10) { - timeFormat = this.days; - } else if (days >= 1) { - timeFormat = this.sdays; - } else if (hours >= 10) { - timeFormat = this.hours; - }else if(hours >= 1){ - timeFormat = this.shours; - }else if (mins >= 10){ - timeFormat = this.mins; - }else if (mins >= 1){ - timeFormat = this.smins; - }else if (secs >= 10){ - timeFormat = this.secs; - }else { - timeFormat = this.ssecs; - } - appendCell(timeFormat.format(new Date(p)), null); + appendCell((new SimpleDurationFormat(0, p)).compact(), link); } public void appendNanos(final long p, final String link) { diff --git a/exec/java-exec/src/test/java/org/apache/drill/exec/server/TestDurationFormat.java b/exec/java-exec/src/test/java/org/apache/drill/exec/server/TestDurationFormat.java new file mode 100644 index 00000000000..f1d3037642d --- /dev/null +++ b/exec/java-exec/src/test/java/org/apache/drill/exec/server/TestDurationFormat.java @@ -0,0 +1,115 @@ +/** + * Licensed to the Apache Software Foundation (ASF) under one + * or more contributor license agreements. See the NOTICE file + * distributed with this work for additional information + * regarding copyright ownership. The ASF licenses this file + * to you under the Apache License, Version 2.0 (the + * "License"); you may not use this file except in compliance + * with the License. You may obtain a copy of the License at + * + * http://www.apache.org/licenses/LICENSE-2.0 + * + * Unless required by applicable law or agreed to in writing, software + * distributed under the License is distributed on an "AS IS" BASIS, + * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied. + * See the License for the specific language governing permissions and + * limitations under the License. + */ +package org.apache.drill.exec.server; + +import org.apache.drill.exec.server.rest.profile.SimpleDurationFormat; +import org.apache.drill.test.DrillTest; +import static org.junit.Assert.assertEquals; + +import org.junit.Test; + +/** + * Test translation of millisecond durations into human readable format + */ +public class TestDurationFormat extends DrillTest { + enum DurationFormat { + COMPACT, + VERBOSE + } + + private void validateDurationFormat(long durationInMillisec, String expected, DurationFormat format) { + String formatted = null; + if (format.equals(DurationFormat.COMPACT)) { + formatted = new SimpleDurationFormat(0, durationInMillisec).compact(); + } + else if (format.equals(DurationFormat.VERBOSE)) { + formatted = new SimpleDurationFormat(0, durationInMillisec).verbose(); + } + assertEquals(formatted,expected); + } + + @Test + public void testCompactTwoDigitMilliSec() { + validateDurationFormat(45, "0.045s", DurationFormat.COMPACT); + } + + @Test + public void testVerboseTwoDigitMilliSec() { + validateDurationFormat(45, "0.045 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactSecMillis() { + validateDurationFormat(4545, "4.545s", DurationFormat.COMPACT); + } + + @Test + public void testVerboseSecMillis() { + validateDurationFormat(4545, "4.545 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactMinSec() { + validateDurationFormat(454534, "7m34s", DurationFormat.COMPACT); + } + + @Test + public void testVerboseMinSec() { + validateDurationFormat(454534, "07 min 34.534 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactHourMin() { + validateDurationFormat(4545342, "1h15m", DurationFormat.COMPACT); + } + + @Test + public void testVerboseHourMin() { + validateDurationFormat(4545342, "1 hr 15 min 45.342 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactHalfDayHourMin() { + validateDurationFormat(45453420, "12h37m", DurationFormat.COMPACT); + } + + @Test + public void testVerboseHalfDayHourMin() { + validateDurationFormat(45453420, "12 hr 37 min 33.420 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactOneDayHourMin() { + validateDurationFormat(45453420 + 86400000, "1d12h37m", DurationFormat.COMPACT); + } + + @Test + public void testVerboseOneDayHourMin() { + validateDurationFormat(45453420 + 86400000, "1 day 12 hr 37 min 33.420 sec", DurationFormat.VERBOSE); + } + + @Test + public void testCompactManyDayHourMin() { + validateDurationFormat(45453420 + 20*86400000, "20d12h37m", DurationFormat.COMPACT); + } + + @Test + public void testVerboseManyDayHourMin() { + validateDurationFormat(45453420 + 20*86400000, "20 day 12 hr 37 min 33.420 sec", DurationFormat.VERBOSE); + } +}