From 2c6e94cfdd26a4cb81e48421b3d346bf6a2dfba1 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Thu, 23 Jan 2025 01:24:55 +0530 Subject: [PATCH 1/9] Add mutation metrics --- .gitignore | 1 + .../apache/phoenix/execute/MutationState.java | 4 +- .../apache/phoenix/jdbc/PhoenixStatement.java | 39 ++++++- .../apache/phoenix/monitoring/MetricType.java | 18 +++ .../monitoring/MutationMetricQueue.java | 73 ++++++++++-- .../monitoring/TableClientMetrics.java | 17 ++- .../phoenix/util/DefaultEnvironmentEdge.java | 5 + .../apache/phoenix/util/EnvironmentEdge.java | 13 +++ .../phoenix/util/EnvironmentEdgeManager.java | 10 ++ .../phoenix/util/ManualEnvironmentEdge.java | 26 ++++- .../apache/phoenix/util/PhoenixRuntime.java | 8 ++ .../PhoenixTableLevelMetricsIT.java | 106 ++++++++++++++---- .../monitoring/TableMetricsManagerTest.java | 36 ++++-- 13 files changed, 301 insertions(+), 55 deletions(-) diff --git a/.gitignore b/.gitignore index bebe16f2800..bd215757262 100644 --- a/.gitignore +++ b/.gitignore @@ -35,3 +35,4 @@ phoenix-hbase-compat-1.5.0/ # Vim swap files .*.sw* +.codegenie diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/execute/MutationState.java b/phoenix-core-client/src/main/java/org/apache/phoenix/execute/MutationState.java index c1bb46fc852..1df6f688cfb 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/execute/MutationState.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/execute/MutationState.java @@ -1724,7 +1724,7 @@ public static MutationMetricQueue.MutationMetric updateMutationBatchFailureMetri numUpsertMutationsInBatch, allUpsertsMutations ? 1 : 0, numDeleteMutationsInBatch, - allDeletesMutations ? 1 : 0); + allDeletesMutations ? 1 : 0, 0, 0, 0, 0, 0, 0); } /** @@ -1807,7 +1807,7 @@ static MutationMetric getCommittedMutationsMetric( committedDeleteMutationCounter, committedTotalMutationBytes, numFailedPhase3Mutations, - 0, 0, 0, 0 ); + 0, 0, 0, 0, 0, 0, 0, 0, 0, 0); } private void filterIndexCheckerMutations(Map> mutationMap, diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java index 8c0e5cafe9f..9ece871fe8f 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java @@ -234,6 +234,7 @@ import org.apache.phoenix.util.ValidateLastDDLTimestampUtil; import org.slf4j.Logger; import org.slf4j.LoggerFactory; +import static org.apache.phoenix.monitoring.MutationMetricQueue.MutationMetric; import org.apache.phoenix.thirdparty.com.google.common.base.Throwables; import org.apache.phoenix.thirdparty.com.google.common.collect.ListMultimap; @@ -606,6 +607,7 @@ private Pair executeMutation(final CompilableStatement stmt, new CallRunner.CallableThrowable, SQLException>() { @Override public Pair call() throws SQLException { + final long startExecuteMutationTime = EnvironmentEdgeManager.timeMarkerInNanos(); boolean success = false; String tableName = null; boolean isUpsert = false; @@ -613,8 +615,9 @@ public Pair call() throws SQLException { boolean isDelete = false; MutationState state = null; MutationPlan plan = null; - final long startExecuteMutationTime = EnvironmentEdgeManager.currentTimeMillis(); clearResultSet(); + long mutationPlanCreationTimeInNs = 0; + long mutationPlanExecutionTimeInNs = 0; try { PhoenixConnection conn = getConnection(); if (conn.getQueryServices().isUpgradeRequired() && !conn.isRunningUpgrade() @@ -624,6 +627,7 @@ public Pair call() throws SQLException { state = connection.getMutationState(); isUpsert = stmt instanceof ExecutableUpsertStatement; isDelete = stmt instanceof ExecutableDeleteStatement; + long mutationPlanCreationStartTimeMarker = EnvironmentEdgeManager.timeMarkerInNanos(); if (isDelete && connection.getAutoCommit() && returnResult == ReturnResult.ROW) { // used only if single row deletion needs to atomically @@ -635,6 +639,8 @@ public Pair call() throws SQLException { plan = stmt.compilePlan(PhoenixStatement.this, Sequence.ValueOp.VALIDATE_SEQUENCE); } + mutationPlanCreationTimeInNs = EnvironmentEdgeManager.timeMarkerInNanos() - + mutationPlanCreationStartTimeMarker; isAtomicUpsert = isUpsert && ((ExecutableUpsertStatement)stmt).getOnDupKeyPairs() != null; if (plan.getTargetRef() != null && plan.getTargetRef().getTable() != null) { if (!Strings.isNullOrEmpty(plan.getTargetRef().getTable().getPhysicalName().toString())) { @@ -648,7 +654,10 @@ public Pair call() throws SQLException { state.sendUncommitted(tableRefs); state.checkpointIfNeccessary(plan); checkIfDDLStatementandMutationState(stmt, state); + long mutationPlanExecutionStartTimeMarker = EnvironmentEdgeManager.timeMarkerInNanos(); MutationState lastState = plan.execute(); + mutationPlanExecutionTimeInNs = EnvironmentEdgeManager.timeMarkerInNanos() - + mutationPlanExecutionStartTimeMarker; state.join(lastState); // Unfortunately, JDBC uses an int for update count, so we // just max out at Integer.MAX_VALUE @@ -718,8 +727,10 @@ public Pair call() throws SQLException { MUTATION_SQL_COUNTER, 1); // Only count dml operations if (isUpsert || isDelete) { - long executeMutationTimeSpent = - EnvironmentEdgeManager.currentTimeMillis() - startExecuteMutationTime; + long executeMutationTimeSpentInNs = + EnvironmentEdgeManager.timeMarkerInNanos() - startExecuteMutationTime; + // This will ensure existing use cases of metrics are not broken. + long executeMutationTimeSpent = PhoenixRuntime.convertTimeInNsToMs(executeMutationTimeSpentInNs); TableMetricsManager.updateMetricsMethod(tableName, isUpsert ? UPSERT_SQL_COUNTER : DELETE_SQL_COUNTER, 1); @@ -731,6 +742,19 @@ public Pair call() throws SQLException { TableMetricsManager.updateMetricsMethod(tableName, ATOMIC_UPSERT_SQL_QUERY_TIME, executeMutationTimeSpent); } + MutationMetric stagedMutationMetric; + if (isUpsert) { + stagedMutationMetric = getStagedMutationMetric( + mutationPlanCreationTimeInNs, mutationPlanExecutionTimeInNs, + 0, 0, + executeMutationTimeSpentInNs, 0); + } + else { + stagedMutationMetric = getStagedMutationMetric(0, 0, + mutationPlanCreationTimeInNs, mutationPlanExecutionTimeInNs, + 0, executeMutationTimeSpentInNs); + } + state.getMutationMetricQueue().addMetricsForTable(tableName, stagedMutationMetric); if (success) { TableMetricsManager.updateMetricsMethod(tableName, isUpsert ? @@ -753,6 +777,7 @@ public Pair call() throws SQLException { state.addExecuteMutationTime( executeMutationTimeSpent, tableName); } + } } @@ -773,6 +798,14 @@ public Pair call() throws SQLException { } } + private MutationMetric getStagedMutationMetric(long upsertMutationPlanCreationTime, long upsertMutationPlanExecutionTime, + long deleteMutationPlanCreationTime, long deleteMutationPlanExecutionTime, + long upsertExecuteMutationTime, long deleteExecuteMutationTime) { + return new MutationMetric(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, + upsertMutationPlanCreationTime, upsertMutationPlanExecutionTime, deleteMutationPlanCreationTime, + deleteMutationPlanExecutionTime, upsertExecuteMutationTime, deleteExecuteMutationTime); + } + /** * Get different Result if the row is atomically deleted. * diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java index d66fb0e19df..ef8b9585285 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MetricType.java @@ -88,6 +88,24 @@ public enum MetricType { DELETE_BATCH_FAILED_COUNTER("dbfc", "Number of delete mutation batches that failed to be committed", LogLevel.OFF, PLong.INSTANCE), + UPSERT_PLAN_CREATION_TIME("upct", "Time taken to create the upsert mutation plan in ns", + LogLevel.OFF, PLong.INSTANCE), + + UPSERT_PLAN_EXECUTION_TIME("upet", "Time taken to execute the upsert mutation plan in ns", + LogLevel.OFF, PLong.INSTANCE), + + UPSERT_EXECUTE_MUTATION_TIME("uemt", "Time taken by upsert in executeMutation in ns", + LogLevel.OFF, PLong.INSTANCE), + + DELETE_PLAN_CREATION_TIME("dpct", "Time taken to create the delete mutation plan in ns", + LogLevel.OFF, PLong.INSTANCE), + + DELETE_PLAN_EXECUTION_TIME("dpet", "Time taken to execute the delete mutation plan in ns", + LogLevel.OFF, PLong.INSTANCE), + + DELETE_EXECUTE_MUTATION_TIME("demt", "Time taken by delete in executeMutation in ns", + LogLevel.OFF, PLong.INSTANCE), + // select-specific query (read) metrics updated during executeQuery SELECT_SUCCESS_SQL_COUNTER("sss", "Counter for number of select sql queries that successfully" + " passed the executeQuery phase", LogLevel.OFF, PLong.INSTANCE), diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MutationMetricQueue.java b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MutationMetricQueue.java index 5a129c09145..58f1f0c834b 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MutationMetricQueue.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/MutationMetricQueue.java @@ -21,13 +21,19 @@ import static org.apache.phoenix.monitoring.MetricType.DELETE_BATCH_FAILED_COUNTER; import static org.apache.phoenix.monitoring.MetricType.DELETE_BATCH_FAILED_SIZE; import static org.apache.phoenix.monitoring.MetricType.DELETE_COMMIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_EXECUTE_MUTATION_TIME; import static org.apache.phoenix.monitoring.MetricType.DELETE_MUTATION_BYTES; import static org.apache.phoenix.monitoring.MetricType.DELETE_MUTATION_SQL_COUNTER; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.MUTATION_BATCH_FAILED_SIZE; import static org.apache.phoenix.monitoring.MetricType.MUTATION_BATCH_SIZE; import static org.apache.phoenix.monitoring.MetricType.MUTATION_BYTES; import static org.apache.phoenix.monitoring.MetricType.MUTATION_COMMIT_TIME; import static org.apache.phoenix.monitoring.MetricType.INDEX_COMMIT_FAILURE_SIZE; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.UPSERT_BATCH_FAILED_COUNTER; import static org.apache.phoenix.monitoring.MetricType.UPSERT_BATCH_FAILED_SIZE; import static org.apache.phoenix.monitoring.MetricType.UPSERT_COMMIT_TIME; @@ -93,7 +99,12 @@ public Map> aggregate() { publishedMetricsForTable.put(metric.getUpsertBatchFailedCounter().getMetricType(), metric.getUpsertBatchFailedCounter().getValue()); publishedMetricsForTable.put(metric.getDeleteBatchFailedSize().getMetricType(), metric.getDeleteBatchFailedSize().getValue()); publishedMetricsForTable.put(metric.getDeleteBatchFailedCounter().getMetricType(), metric.getDeleteBatchFailedCounter().getValue()); - + publishedMetricsForTable.put(metric.getUpsertMutationPlanCreationTime().getMetricType(), metric.getUpsertMutationPlanCreationTime().getValue()); + publishedMetricsForTable.put(metric.getUpsertMutationPlanExecutionTime().getMetricType(), metric.getUpsertMutationPlanExecutionTime().getValue()); + publishedMetricsForTable.put(metric.getDeleteMutationPlanCreationTime().getMetricType(), metric.getDeleteMutationPlanCreationTime().getValue()); + publishedMetricsForTable.put(metric.getDeleteMutationPlanExecutionTime().getMetricType(), metric.getDeleteMutationPlanExecutionTime().getValue()); + publishedMetricsForTable.put(metric.getUpsertExecuteMutationTime().getMetricType(), metric.getUpsertExecuteMutationTime().getValue()); + publishedMetricsForTable.put(metric.getDeleteExecuteMutationTime().getMetricType(), metric.getDeleteExecuteMutationTime().getValue()); } return publishedMetrics; } @@ -125,16 +136,26 @@ public static class MutationMetric { private final CombinableMetric numOfIndexCommitFailMutations = new CombinableMetricImpl( INDEX_COMMIT_FAILURE_SIZE); + private final CombinableMetric upsertMutationPlanCreationTime = new CombinableMetricImpl(UPSERT_PLAN_CREATION_TIME); + private final CombinableMetric upsertMutationPlanExecutionTime = new CombinableMetricImpl(UPSERT_PLAN_EXECUTION_TIME); + private final CombinableMetric deleteMutationPlanCreationTime = new CombinableMetricImpl(DELETE_PLAN_CREATION_TIME); + private final CombinableMetric deleteMutationPlanExecutionTime = new CombinableMetricImpl(DELETE_PLAN_EXECUTION_TIME); + private final CombinableMetric upsertExecuteMutationTime = new CombinableMetricImpl(UPSERT_EXECUTE_MUTATION_TIME); + private final CombinableMetric deleteExecuteMutationTime = new CombinableMetricImpl(DELETE_EXECUTE_MUTATION_TIME); + + public static final MutationMetric EMPTY_METRIC = - new MutationMetric(0,0,0,0, 0, 0,0,0,0,0,0,0,0,0,0); + new MutationMetric(0,0,0,0, 0, 0,0,0,0,0,0,0,0,0,0, 0, 0, 0, 0, 0, 0); public MutationMetric(long numMutations, long upsertMutationsSizeBytes, - long deleteMutationsSizeBytes, long commitTimeForUpserts, long commitTimeForAtomicUpserts, - long commitTimeForDeletes, long numFailedMutations, long upsertMutationSqlCounterSuccess, - long deleteMutationSqlCounterSuccess, long totalMutationBytes, - long numOfPhase3Failed, long upsertBatchFailedSize, - long upsertBatchFailedCounter, long deleteBatchFailedSize, - long deleteBatchFailedCounter) { + long deleteMutationsSizeBytes, long commitTimeForUpserts, long commitTimeForAtomicUpserts, + long commitTimeForDeletes, long numFailedMutations, long upsertMutationSqlCounterSuccess, + long deleteMutationSqlCounterSuccess, long totalMutationBytes, + long numOfPhase3Failed, long upsertBatchFailedSize, + long upsertBatchFailedCounter, long deleteBatchFailedSize, + long deleteBatchFailedCounter, long upsertMutationPlanCreationTime, + long upsertMutationPlanExecutionTime, long deleteMutationPlanCreationTime, + long deleteMutationPlanExecutionTime, long upsertExecuteMutationTime, long deleteExecuteMutationTime) { this.numMutations.change(numMutations); this.totalCommitTimeForUpserts.change(commitTimeForUpserts); this.totalCommitTimeForAtomicUpserts.change(commitTimeForAtomicUpserts); @@ -151,6 +172,12 @@ public MutationMetric(long numMutations, long upsertMutationsSizeBytes, this.upsertBatchFailedCounter.change(upsertBatchFailedCounter); this.deleteBatchFailedSize.change(deleteBatchFailedSize); this.deleteBatchFailedCounter.change(deleteBatchFailedCounter); + this.upsertMutationPlanCreationTime.change(upsertMutationPlanCreationTime); + this.upsertMutationPlanExecutionTime.change(upsertMutationPlanExecutionTime); + this.deleteMutationPlanCreationTime.change(deleteMutationPlanCreationTime); + this.deleteMutationPlanExecutionTime.change(deleteMutationPlanExecutionTime); + this.upsertExecuteMutationTime.change(upsertExecuteMutationTime); + this.deleteExecuteMutationTime.change(deleteExecuteMutationTime); } public CombinableMetric getTotalCommitTimeForUpserts() { @@ -215,6 +242,30 @@ public CombinableMetric getDeleteBatchFailedCounter() { return deleteBatchFailedCounter; } + public CombinableMetric getUpsertMutationPlanCreationTime() { + return upsertMutationPlanCreationTime; + } + + public CombinableMetric getUpsertMutationPlanExecutionTime() { + return upsertMutationPlanExecutionTime; + } + + public CombinableMetric getDeleteMutationPlanCreationTime() { + return deleteMutationPlanCreationTime; + } + + public CombinableMetric getDeleteMutationPlanExecutionTime() { + return deleteMutationPlanExecutionTime; + } + + public CombinableMetric getUpsertExecuteMutationTime() { + return upsertExecuteMutationTime; + } + + public CombinableMetric getDeleteExecuteMutationTime() { + return deleteExecuteMutationTime; + } + public void combineMetric(MutationMetric other) { this.numMutations.combine(other.numMutations); this.totalCommitTimeForUpserts.combine(other.totalCommitTimeForUpserts); @@ -232,6 +283,12 @@ public void combineMetric(MutationMetric other) { this.upsertBatchFailedCounter.combine(other.upsertBatchFailedCounter); this.deleteBatchFailedSize.combine(other.deleteBatchFailedSize); this.deleteBatchFailedCounter.combine(other.deleteBatchFailedCounter); + this.upsertMutationPlanCreationTime.combine(other.upsertMutationPlanCreationTime); + this.upsertMutationPlanExecutionTime.combine(other.upsertMutationPlanExecutionTime); + this.deleteMutationPlanCreationTime.combine(other.deleteMutationPlanCreationTime); + this.deleteMutationPlanExecutionTime.combine(other.deleteMutationPlanExecutionTime); + this.upsertExecuteMutationTime.combine(other.upsertExecuteMutationTime); + this.deleteExecuteMutationTime.combine(other.deleteExecuteMutationTime); } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/TableClientMetrics.java b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/TableClientMetrics.java index 5a1aa3dbc7e..5e9f73bec94 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/TableClientMetrics.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/monitoring/TableClientMetrics.java @@ -74,12 +74,15 @@ import static org.apache.phoenix.monitoring.MetricType.DELETE_AGGREGATE_FAILURE_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.SELECT_AGGREGATE_SUCCESS_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.SELECT_AGGREGATE_FAILURE_SQL_COUNTER; -import static org.apache.phoenix.monitoring.MetricType.NUM_SYSTEM_TABLE_RPC_SUCCESS; -import static org.apache.phoenix.monitoring.MetricType.NUM_SYSTEM_TABLE_RPC_FAILURES; -import static org.apache.phoenix.monitoring.MetricType.TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS; import static org.apache.phoenix.monitoring.MetricType.ATOMIC_UPSERT_COMMIT_TIME; import static org.apache.phoenix.monitoring.MetricType.ATOMIC_UPSERT_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.ATOMIC_UPSERT_SQL_QUERY_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_EXECUTION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_EXECUTION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_EXECUTE_MUTATION_TIME; /** * This is used by TableMetricsManager class to store instance of @@ -140,7 +143,13 @@ public enum TableMetrics { TABLE_NUM_SYSTEM_TABLE_RPC_SUCCESS(NUM_SYSTEM_TABLE_RPC_SUCCESS), TABLE_NUM_SYSTEM_TABLE_RPC_FAILURES(NUM_SYSTEM_TABLE_RPC_FAILURES), TABLE_NUM_METADATA_LOOKUP_FAILURES(NUM_METADATA_LOOKUP_FAILURES), - TABLE_TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS(TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS); + TABLE_TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS(TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS), + TABLE_UPSERT_PLAN_CREATION_TIME(UPSERT_PLAN_CREATION_TIME), + TABLE_UPSERT_PLAN_EXECUTION_TIME(UPSERT_PLAN_EXECUTION_TIME), + TABLE_DELETE_PLAN_CREATION_TIME(DELETE_PLAN_CREATION_TIME), + TABLE_DELETE_PLAN_EXECUTION_TIME(DELETE_PLAN_EXECUTION_TIME), + TABLE_UPSERT_EXECUTE_MUTATION_TIME(UPSERT_EXECUTE_MUTATION_TIME), + TABLE_DELETE_EXECUTE_MUTATION_TIME(DELETE_EXECUTE_MUTATION_TIME); private MetricType metricType; private PhoenixTableMetric metric; diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/DefaultEnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/DefaultEnvironmentEdge.java index 6a1e0755846..dcb353566b2 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/DefaultEnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/DefaultEnvironmentEdge.java @@ -31,4 +31,9 @@ public long currentTime() { return System.currentTimeMillis(); } + @Override + public long nanoTime() { + return System.nanoTime(); + } + } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java index 31e8a4c0d6a..2e0102337be 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java @@ -18,6 +18,8 @@ */ package org.apache.phoenix.util; +import org.apache.commons.lang3.NotImplementedException; + /** * Has some basic interaction with the environment. Alternate implementations * can be used where required (eg in tests). @@ -32,4 +34,15 @@ public abstract class EnvironmentEdge implements org.apache.hadoop.hbase.util.En */ @Override abstract public long currentTime(); + + /** + * This method can be only be used to measure elapsed time. The method returns a time marker + * and if we subtract any two time markers returned by this method, then we get time elapsed + * b/w those two markers in nano seconds. For further details refer to documentation of + * {@link System#nanoTime()}. + * @return a time marker in nano seconds + */ + public long nanoTime() { + throw new NotImplementedException("Not Implemented!"); + } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdgeManager.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdgeManager.java index c5e1a63476c..519ea6a47f5 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdgeManager.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdgeManager.java @@ -75,4 +75,14 @@ public static void injectEdge(EnvironmentEdge edge) { public static long currentTimeMillis() { return getDelegate().currentTime(); } + + /** + * Defers to the delegate and calls the {@link EnvironmentEdge#nanoTime()} method. + * Subtracting two markers will give you the elapsed time in nanos. + * + * @return marker in nano seconds + */ + public static long timeMarkerInNanos() { + return getDelegate().nanoTime(); + } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java index 169e3131caa..7029f3b975f 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java @@ -19,18 +19,40 @@ public class ManualEnvironmentEdge extends EnvironmentEdge { // Sometimes 0 ts might have a special value, so lets start with 1 + // value is in Nano seconds protected long value = 1L; + private long convertMsToNs(long value) { + return value * 1000000; + } + + private long convertNsToMs(long value) { + return value / 1000000; + } + public void setValue(long newValue) { - value = newValue; + value = convertMsToNs(newValue); } public void incrementValue(long addedValue) { - value += addedValue; + value += convertMsToNs(addedValue); } @Override public long currentTime() { + return convertNsToMs(this.value); + } + + @Override + public long nanoTime() { return this.value; } + + public void setValueInNs(long newValue) { + this.value = newValue; + } + + public void incrementValueInNs(long newValue) { + this.value += newValue; + } } \ No newline at end of file diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java index 88ad2e36eff..10d15b462cc 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java @@ -1660,4 +1660,12 @@ public static long getCurrentScn(ReadOnlyProps props) { String scn = props.get(CURRENT_SCN_ATTRIB); return scn != null ? Long.parseLong(scn) : HConstants.LATEST_TIMESTAMP; } + + public static long convertTimeInNsToMs(long value) { + return value / 1000000; + } + + public static long convertTimeInMsToNs(long value) { + return value * 1000000; + } } diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index 0031957cfa3..a50350bcb0d 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -38,7 +38,6 @@ import org.apache.phoenix.query.ConnectionQueryServices; import org.apache.phoenix.query.ConnectionQueryServicesImpl; import org.apache.phoenix.query.QueryServices; -import org.apache.phoenix.query.QueryServicesOptions; import org.apache.phoenix.query.QueryServicesTestImpl; import org.apache.phoenix.util.EnvironmentEdge; import org.apache.phoenix.util.EnvironmentEdgeManager; @@ -67,6 +66,12 @@ import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_MUTATION_BYTES; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_QUERY_TIME; import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_SCAN_BYTES; +import static org.apache.phoenix.monitoring.MetricType.DELETE_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_EXECUTION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.NUM_SYSTEM_TABLE_RPC_SUCCESS; import static org.apache.phoenix.monitoring.MetricType.DELETE_AGGREGATE_FAILURE_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.DELETE_AGGREGATE_SUCCESS_SQL_COUNTER; @@ -120,10 +125,12 @@ import static org.apache.phoenix.util.DelayedOrFailingRegionServer.INJECTED_EXCEPTION_STRING; import static org.apache.phoenix.util.PhoenixRuntime.JDBC_PROTOCOL_SEPARATOR; import static org.apache.phoenix.util.PhoenixRuntime.clearTableLevelMetrics; +import static org.apache.phoenix.util.PhoenixRuntime.convertTimeInNsToMs; import static org.apache.phoenix.util.PhoenixRuntime.getOverAllReadRequestMetricInfo; import static org.apache.phoenix.util.PhoenixRuntime.getPhoenixTableClientMetrics; import static org.apache.phoenix.util.PhoenixRuntime.getRequestReadMetricInfo; import static org.apache.phoenix.util.PhoenixRuntime.getWriteMetricInfoForMutationsSinceLastReset; +import static org.apache.phoenix.util.PhoenixRuntime.convertTimeInMsToNs; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull; @@ -152,6 +159,8 @@ public class PhoenixTableLevelMetricsIT extends BaseTest { private static final String UPSERT_DML = "UPSERT INTO %s VALUES (?, ?)"; private static final String KEY = "key"; private static final String VALUE = "value"; + private static final int CLOCK_DELAY = 1; + private static final int MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION = 5; private static boolean failExecuteQueryAndClientSideDeletes; private static long injectDelay; private static HBaseTestingUtility hbaseTestUtil; @@ -187,6 +196,8 @@ public class PhoenixTableLevelMetricsIT extends BaseTest { Map props = Maps.newHashMapWithExpectedSize(1); props.put(BaseTest.DRIVER_CLASS_NAME_ATTRIB, PhoenixMetricsTestingDriver.class.getName()); initAndRegisterTestDriver(url, new ReadOnlyProps(props.entrySet().iterator())); + MyClock clock = new MyClock(System.currentTimeMillis(), CLOCK_DELAY); + EnvironmentEdgeManager.injectEdge(clock); // This will ensure at least one 1 ms is elapsed in executeMutation call } @AfterClass public static void tearDownMiniCluster() { @@ -342,7 +353,10 @@ private static void assertMutationTableMetrics(final boolean isUpsert, final Str final long expectedUpsertOrDeleteAggregateSuccessCt, final long expectedUpsertOrDeleteAggregateFailureCt, final Map writeMutMetrics, final Connection conn, - final boolean expectedSystemCatalogMetric) + final boolean expectedSystemCatalogMetric, + final long expectedMinMutationPlanCreationTime, + final long expectedMinMutationPlanExecutionTime, + final long expectedMinExecuteMutationTime) throws SQLException { assertTrue(conn != null && conn.isClosed()); assertFalse(hasMutationBeenExplicitlyCommitted && writeMutMetrics == null); @@ -365,6 +379,21 @@ private static void assertMutationTableMetrics(final boolean isUpsert, final Str expectedUpsertOrDeleteFailedSqlCt, CompareOp.EQ); assertMetricValue(metric, isUpsert ? UPSERT_SQL_QUERY_TIME : DELETE_SQL_QUERY_TIME, expectedMinUpsertOrDeleteSqlQueryTime, CompareOp.GTEQ); + assertMetricValue(metric, isUpsert ? UPSERT_PLAN_CREATION_TIME : DELETE_PLAN_CREATION_TIME, + writeMutMetrics.get(isUpsert ? UPSERT_PLAN_CREATION_TIME : DELETE_PLAN_CREATION_TIME), + CompareOp.EQ); + assertMetricValue(metric, isUpsert ? UPSERT_PLAN_CREATION_TIME : DELETE_PLAN_CREATION_TIME, + expectedMinMutationPlanCreationTime, CompareOp.GTEQ); + assertMetricValue(metric, isUpsert ? UPSERT_PLAN_EXECUTION_TIME : DELETE_PLAN_EXECUTION_TIME, + writeMutMetrics.get(isUpsert ? UPSERT_PLAN_EXECUTION_TIME : DELETE_PLAN_EXECUTION_TIME), + CompareOp.EQ); + assertMetricValue(metric, isUpsert ? UPSERT_PLAN_EXECUTION_TIME : DELETE_PLAN_EXECUTION_TIME, + expectedMinMutationPlanExecutionTime, CompareOp.GTEQ); + assertMetricValue(metric, isUpsert ? UPSERT_EXECUTE_MUTATION_TIME : DELETE_EXECUTE_MUTATION_TIME, + writeMutMetrics.get(isUpsert ? UPSERT_EXECUTE_MUTATION_TIME : DELETE_EXECUTE_MUTATION_TIME), + CompareOp.EQ); + assertMetricValue(metric, isUpsert ? UPSERT_EXECUTE_MUTATION_TIME : DELETE_EXECUTE_MUTATION_TIME, + expectedMinExecuteMutationTime, CompareOp.GTEQ); if(expectedSystemCatalogMetric){ assertMetricValue(metric,NUM_SYSTEM_TABLE_RPC_SUCCESS,0,CompareOp.GT); assertMetricValue(metric,TIME_SPENT_IN_SYSTEM_TABLE_RPC_CALLS,0,CompareOp.GT); @@ -691,7 +720,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa @Test public void testTableLevelMetricsForUpsert() throws Throwable { String tableName = generateUniqueName(); - int numRows = 10000; + int numRows = 1; Connection conn = null; Throwable exception = null; try { @@ -712,8 +741,11 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa conn.close(); // Must be asserted after connection close since that's where // we populate table-level metrics - assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, 0, 0, 1, 0, - writeMutMetrics, conn, true); + assertMutationTableMetrics(true, tableName, numRows, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * numRows, + true, numRows, 0, 0, 1, 0, + writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); } } @@ -738,8 +770,12 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, 0, 0, 1, 0, - writeMutMetrics, conn, true); + assertMutationTableMetrics(true, tableName, numRows, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * numRows, true, numRows, + 0, 0, 1, 0, + writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInNsToMs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); } } @@ -779,7 +815,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa // mutation commit time since autoCommit was on assertMutationTableMetrics(true, tableName, numRows, 0, writeMutMetrics.get(UPSERT_COMMIT_TIME), true, numRows, 0, 0, numRows, 0, - writeMutMetrics, conn,true); + writeMutMetrics, conn,true, 0, 0, 0); } } @@ -813,8 +849,12 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa throw exception; } assertNotNull("Failed to get a connection!", conn); + Map + writeMutMetrics = + getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, 0, 1, 0, false, 0, 0, 0, 1, 0, null, conn, true); + assertMutationTableMetrics(true, tableName, 0, 1, 0, false, 0, 0, 0, 1, 0, + writeMutMetrics, conn, true, 0, 0, 0); } } @@ -853,8 +893,9 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, numRows, 0, delay, true, numRows, 0, 0, 1, - 0, writeMutMetrics, conn, true); + assertMutationTableMetrics(true, tableName, numRows, 0, 5 * delay * numRows, true, numRows, 0, 0, 1, + 0, writeMutMetrics, conn, true, + convertTimeInMsToNs(delay) * numRows, convertTimeInMsToNs(delay) * numRows, convertTimeInMsToNs(5 * delay) * numRows); } } @@ -902,7 +943,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, 0, 1, 0, true, 1, 0, 1, 0, 1, - writeMutMetrics, conn, true); + writeMutMetrics, conn, true, 0, 0, 0); } } @@ -953,7 +994,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, 0, numRows, 0, - 1, writeMutMetrics, conn, true); + 1, writeMutMetrics, conn, true, 0, 0, 0); } } @@ -993,7 +1034,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, delayRs, 0, 1, - 0, writeMutMetrics, conn, true); + 0, writeMutMetrics, conn, true, 0, 0, 0); } } @@ -1024,7 +1065,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, 0, true, 1, 0, 0, 1, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1055,7 +1096,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, 0, true, numRows, 0, 0, 1, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1088,11 +1129,11 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); // When autoCommit = true, deletes happen on the server and so mutation metrics are not - // accumulated for those mutations - assertNull(writeMutMetrics); + // accumulated for those mutations except of the ones collected in executeMutation method + assertNotNull(writeMutMetrics); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, 0, false, 0, 0, 0, 0, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1136,7 +1177,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); assertNull(writeMutMetrics); conn.close(); - assertMutationTableMetrics(false, tableName, 0, 1, 0, false, 0, 0, 0, 0, 1, null, conn, false); + assertMutationTableMetrics(false, tableName, 0, 1, 0, false, 0, 0, 0, 0, 1, null, conn, false, 0, 0, 0); } } @@ -1175,7 +1216,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, injectDelay, true, 1, 0, 0, 1, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1221,7 +1262,7 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, 0, true, numRows, 0, numRows, 0, 1, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1255,6 +1296,18 @@ public void testMetricsWithIndexUsage() throws Exception { } conn.commit(); } + // Assert that mutation plan creation and execution metrics have captured only for + // data table and not index table + for(PhoenixTableMetric metric: getPhoenixTableClientMetrics().get(dataTable)) { + assertMetricValue(metric, UPSERT_PLAN_CREATION_TIME, 0, CompareOp.GTEQ); + assertMetricValue(metric, UPSERT_PLAN_EXECUTION_TIME, 0, CompareOp.GTEQ); + assertMetricValue(metric, UPSERT_EXECUTE_MUTATION_TIME, 0, CompareOp.GTEQ); + } + for(PhoenixTableMetric metric: getPhoenixTableClientMetrics().get(indexName)) { + assertMetricValue(metric, UPSERT_PLAN_CREATION_TIME, 0, CompareOp.EQ); + assertMetricValue(metric, UPSERT_PLAN_EXECUTION_TIME, 0, CompareOp.EQ); + assertMetricValue(metric, UPSERT_EXECUTE_MUTATION_TIME, 0, CompareOp.EQ); + } // Check if the index is being used try (Connection conn = getConnFromTestDriver()) { @@ -1332,7 +1385,7 @@ public void testMetricsWithIndexUsage() throws Exception { getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(false, tableName, 1, 0, 0, true, numRows, delayRs, 0, 1, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); } } @@ -1374,7 +1427,7 @@ public void testMetricsWithIndexUsage() throws Exception { // 1 regular upsert + numAtomicUpserts // 2 mutations (regular and atomic on the same row in the same batch will be split) assertMutationTableMetrics(true, tableName, 1 + numAtomicUpserts, 0, 0, true, 2, 0, 0, 2, 0, - writeMutMetrics, conn, false); + writeMutMetrics, conn, false, 0, 0, 0); assertEquals(numAtomicUpserts, getMetricFromTableMetrics(tableName, ATOMIC_UPSERT_SQL_COUNTER)); assertTrue(getMetricFromTableMetrics(tableName, ATOMIC_UPSERT_COMMIT_TIME) > 0); } @@ -1553,6 +1606,11 @@ public MyClock(long time, long delay) { this.time.addAndGet(this.delay); return currentTime; } + + @Override + public long nanoTime() { + return convertTimeInMsToNs(currentTime()); + } } /** diff --git a/phoenix-core/src/test/java/org/apache/phoenix/monitoring/TableMetricsManagerTest.java b/phoenix-core/src/test/java/org/apache/phoenix/monitoring/TableMetricsManagerTest.java index 54f4c6c6137..67200e88b50 100644 --- a/phoenix-core/src/test/java/org/apache/phoenix/monitoring/TableMetricsManagerTest.java +++ b/phoenix-core/src/test/java/org/apache/phoenix/monitoring/TableMetricsManagerTest.java @@ -236,32 +236,38 @@ public void testHistogramMetricsForUpsertMutations() { TableMetricsManager.updateLatencyHistogramForMutations(tableName, 1, true); MutationMetricQueue.MutationMetric metric = new MutationMetricQueue.MutationMetric( 0L, 5L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 5L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 5L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 2, true); metric = new MutationMetricQueue.MutationMetric(0L, 10L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 10L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 10L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 4, true); metric = new MutationMetricQueue.MutationMetric(0L, 50L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 50L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 50L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 5, true); metric = new MutationMetricQueue.MutationMetric(0L, 100L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 100L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 100L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 6, true); metric = new MutationMetricQueue.MutationMetric(0L, 500L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 500L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 500L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 8, true); metric = new MutationMetricQueue.MutationMetric(0L, 1000L, 0L, 0L, 0L,0L, - 0L, 1L, 0L, 1000L, 0L, 0L, 0L, 0L, 0L); + 0L, 1L, 0L, 1000L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), true); @@ -300,32 +306,38 @@ public void testHistogramMetricsForDeleteMutations() { TableMetricsManager.updateLatencyHistogramForMutations(tableName, 1, false); MutationMetricQueue.MutationMetric metric = new MutationMetricQueue.MutationMetric( 0L, 0L, 5L, 0L, 0L, 0L, - 0L, 0L, 1L, 5L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 5L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 2, false); metric = new MutationMetricQueue.MutationMetric(0L, 0L, 10L, 0L, 0L, 0L, - 0L, 0L, 1L, 10L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 10L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 4, false); metric = new MutationMetricQueue.MutationMetric(0L, 0L, 50L, 0L, 0L, 0L, - 0L, 0L, 1L, 50L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 50L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 5,false); metric = new MutationMetricQueue.MutationMetric(0L, 0L, 100L, 0L, 0L, 0L, - 0L, 0L, 1L, 100L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 100L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 6,false); metric = new MutationMetricQueue.MutationMetric(0L, 0L, 500L, 0L, 0L, 0L, - 0L, 0L, 1L, 500L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 500L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); TableMetricsManager.updateLatencyHistogramForMutations(tableName, 8, false); metric = new MutationMetricQueue.MutationMetric(0L, 0L, 1000L, 0L, 0L, 0L, - 0L, 0L, 1L, 1000L, 0L, 0L, 0L, 0L, 0L); + 0L, 0L, 1L, 1000L, 0L, 0L, 0L, 0L, 0L, + 0L, 0L, 0L, 0L, 0L, 0L); TableMetricsManager.updateSizeHistogramMetricsForMutations(tableName, metric.getTotalMutationsSizeBytes().getValue(), false); From 5b7bf61513ecd1dfea6ef319af61c3d1b1e84b8c Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Thu, 23 Jan 2025 13:56:55 +0530 Subject: [PATCH 2/9] Add test coverage --- .../PhoenixTableLevelMetricsIT.java | 129 +++++++++++++----- 1 file changed, 97 insertions(+), 32 deletions(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index a50350bcb0d..b5d6b56833a 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -39,6 +39,7 @@ import org.apache.phoenix.query.ConnectionQueryServicesImpl; import org.apache.phoenix.query.QueryServices; import org.apache.phoenix.query.QueryServicesTestImpl; +import org.apache.phoenix.util.DefaultEnvironmentEdge; import org.apache.phoenix.util.EnvironmentEdge; import org.apache.phoenix.util.EnvironmentEdgeManager; import org.apache.phoenix.util.InstanceResolver; @@ -125,7 +126,6 @@ import static org.apache.phoenix.util.DelayedOrFailingRegionServer.INJECTED_EXCEPTION_STRING; import static org.apache.phoenix.util.PhoenixRuntime.JDBC_PROTOCOL_SEPARATOR; import static org.apache.phoenix.util.PhoenixRuntime.clearTableLevelMetrics; -import static org.apache.phoenix.util.PhoenixRuntime.convertTimeInNsToMs; import static org.apache.phoenix.util.PhoenixRuntime.getOverAllReadRequestMetricInfo; import static org.apache.phoenix.util.PhoenixRuntime.getPhoenixTableClientMetrics; import static org.apache.phoenix.util.PhoenixRuntime.getRequestReadMetricInfo; @@ -196,8 +196,11 @@ public class PhoenixTableLevelMetricsIT extends BaseTest { Map props = Maps.newHashMapWithExpectedSize(1); props.put(BaseTest.DRIVER_CLASS_NAME_ATTRIB, PhoenixMetricsTestingDriver.class.getName()); initAndRegisterTestDriver(url, new ReadOnlyProps(props.entrySet().iterator())); - MyClock clock = new MyClock(System.currentTimeMillis(), CLOCK_DELAY); - EnvironmentEdgeManager.injectEdge(clock); // This will ensure at least one 1 ms is elapsed in executeMutation call + } + + private void useCustomClock() { + MyClock clock = new MyClock(10, CLOCK_DELAY); + EnvironmentEdgeManager.injectEdge(clock); } @AfterClass public static void tearDownMiniCluster() { @@ -719,8 +722,9 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa } @Test public void testTableLevelMetricsForUpsert() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); - int numRows = 1; + int numRows = 10000; Connection conn = null; Throwable exception = null; try { @@ -744,12 +748,15 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa assertMutationTableMetrics(true, tableName, numRows, 0, MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * numRows, true, numRows, 0, 0, 1, 0, - writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, - convertTimeInMsToNs(CLOCK_DELAY) * numRows, convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); + writeMutMetrics, conn, true, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); } } @Test public void testTableLevelMetricsForBatchUpserts() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); int numRows = 20; Connection conn = null; @@ -771,15 +778,17 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, numRows, 0, - MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * numRows, true, numRows, - 0, 0, 1, 0, - writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, - convertTimeInNsToMs(CLOCK_DELAY) * numRows, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * numRows, + true, numRows, 0, 0, 1, 0, + writeMutMetrics, conn, true, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); } } @Test public void testTableLevelMetricsAutoCommitTrueUpsert() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); String ddl = String.format(CREATE_TABLE_DDL, tableName, 20); int numRows = 10; @@ -815,11 +824,15 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, // mutation commit time since autoCommit was on assertMutationTableMetrics(true, tableName, numRows, 0, writeMutMetrics.get(UPSERT_COMMIT_TIME), true, numRows, 0, 0, numRows, 0, - writeMutMetrics, conn,true, 0, 0, 0); + writeMutMetrics, conn,true, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(CLOCK_DELAY) * numRows, + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * numRows); } } @Test public void testTableLevelMetricsforFailingUpsert() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); // Restrict the key to just 2 characters so that we fail later String ddl = String.format(CREATE_TABLE_DDL, tableName, 2); @@ -854,11 +867,14 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, 0, 1, 0, false, 0, 0, 0, 1, 0, - writeMutMetrics, conn, true, 0, 0, 0); + writeMutMetrics, conn, true, + convertTimeInMsToNs(CLOCK_DELAY), 0, + convertTimeInMsToNs(3 * CLOCK_DELAY)); } } @Test public void testTableLevelMetricsforUpsertSqlTime() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); String ddl = String.format(CREATE_TABLE_DDL, tableName, 10); int numRows = 10; @@ -895,11 +911,14 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, conn.close(); assertMutationTableMetrics(true, tableName, numRows, 0, 5 * delay * numRows, true, numRows, 0, 0, 1, 0, writeMutMetrics, conn, true, - convertTimeInMsToNs(delay) * numRows, convertTimeInMsToNs(delay) * numRows, convertTimeInMsToNs(5 * delay) * numRows); + convertTimeInMsToNs(delay) * numRows, + convertTimeInMsToNs(delay) * numRows, + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * delay) * numRows); } } @Test public void testTableLevelMetricsUpsertCommitFailedWithAutoCommitTrue() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); String ddl = String.format(CREATE_TABLE_DDL, tableName, 10); int numRows = 10; @@ -942,12 +961,18 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, 0, 1, 0, true, 1, 0, 1, 0, 1, - writeMutMetrics, conn, true, 0, 0, 0); + assertMutationTableMetrics(true, tableName, 0, 1, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + true, 1, 0, 1, 0, 1, + writeMutMetrics, conn, true, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @Test public void testTableLevelMetricsUpsertCommitFailed() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); String ddl = String.format(CREATE_TABLE_DDL, tableName, 10); int numRows = 10; @@ -993,8 +1018,13 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, 0, numRows, 0, - 1, writeMutMetrics, conn, true, 0, 0, 0); + assertMutationTableMetrics(true, tableName, numRows, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + true, numRows, 0, numRows, 0, + 1, writeMutMetrics, conn, true, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @@ -1033,12 +1063,16 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, numRows, 0, 0, true, numRows, delayRs, 0, 1, - 0, writeMutMetrics, conn, true, 0, 0, 0); + assertMutationTableMetrics(true, tableName, numRows, 0, + 0, + true, numRows, delayRs, 0, 1, + 0, writeMutMetrics, conn, true, + 0, 0, 0); } } @Test public void testTableLevelMetricsForPointDelete() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); int numRows = 15; Connection conn = null; @@ -1064,12 +1098,18 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(false, tableName, 1, 0, 0, true, 1, 0, 0, 1, 0, - writeMutMetrics, conn, false, 0, 0, 0); + assertMutationTableMetrics(false, tableName, 1, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + true, 1, 0, 0, 1, 0, + writeMutMetrics, conn, false, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @Test public void testTableLevelMetricsForDeleteAll() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); int numRows = 15; Connection conn = null; @@ -1095,12 +1135,18 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(false, tableName, 1, 0, 0, true, numRows, 0, 0, 1, 0, - writeMutMetrics, conn, false, 0, 0, 0); + assertMutationTableMetrics(false, tableName, 1, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + true, numRows, 0, 0, 1, 0, + writeMutMetrics, conn, false, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @Test public void testTableLevelMetricsAutoCommitTrueDelete() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); int numRows = 15; Connection conn = null; @@ -1132,8 +1178,13 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, // accumulated for those mutations except of the ones collected in executeMutation method assertNotNull(writeMutMetrics); conn.close(); - assertMutationTableMetrics(false, tableName, 1, 0, 0, false, 0, 0, 0, 0, 0, - writeMutMetrics, conn, false, 0, 0, 0); + assertMutationTableMetrics(false, tableName, 1, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + false, 0, 0, 0, 0, 0, + writeMutMetrics, conn, false, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @@ -1221,6 +1272,7 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, } @Test public void testTableLevelMetricsDeleteCommitFailed() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); int numRows = 15; Connection conn = null; @@ -1261,13 +1313,19 @@ writeMutMetrics, conn, true, convertTimeInMsToNs(CLOCK_DELAY) * numRows, writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(false, tableName, 1, 0, 0, true, numRows, 0, numRows, 0, 1, - writeMutMetrics, conn, false, 0, 0, 0); + assertMutationTableMetrics(false, tableName, 1, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY, + true, numRows, 0, numRows, 0, 1, + writeMutMetrics, conn, false, + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(CLOCK_DELAY), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY)); } } @Test public void testMetricsWithIndexUsage() throws Exception { + useCustomClock(); // Generate unique names for the table and index String dataTable = generateUniqueName(); String indexName = generateUniqueName() + "_IDX"; @@ -1299,9 +1357,10 @@ public void testMetricsWithIndexUsage() throws Exception { // Assert that mutation plan creation and execution metrics have captured only for // data table and not index table for(PhoenixTableMetric metric: getPhoenixTableClientMetrics().get(dataTable)) { - assertMetricValue(metric, UPSERT_PLAN_CREATION_TIME, 0, CompareOp.GTEQ); - assertMetricValue(metric, UPSERT_PLAN_EXECUTION_TIME, 0, CompareOp.GTEQ); - assertMetricValue(metric, UPSERT_EXECUTE_MUTATION_TIME, 0, CompareOp.GTEQ); + assertMetricValue(metric, UPSERT_PLAN_CREATION_TIME, convertTimeInMsToNs(CLOCK_DELAY), CompareOp.GTEQ); + assertMetricValue(metric, UPSERT_PLAN_EXECUTION_TIME, convertTimeInMsToNs(CLOCK_DELAY), CompareOp.GTEQ); + assertMetricValue(metric, UPSERT_EXECUTE_MUTATION_TIME, + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY), CompareOp.GTEQ); } for(PhoenixTableMetric metric: getPhoenixTableClientMetrics().get(indexName)) { assertMetricValue(metric, UPSERT_PLAN_CREATION_TIME, 0, CompareOp.EQ); @@ -1390,6 +1449,7 @@ public void testMetricsWithIndexUsage() throws Exception { } @Test public void testTableLevelMetricsForAtomicUpserts() throws Throwable { + useCustomClock(); String tableName = generateUniqueName(); Connection conn = null; Throwable exception = null; @@ -1426,8 +1486,13 @@ public void testMetricsWithIndexUsage() throws Exception { conn.close(); // 1 regular upsert + numAtomicUpserts // 2 mutations (regular and atomic on the same row in the same batch will be split) - assertMutationTableMetrics(true, tableName, 1 + numAtomicUpserts, 0, 0, true, 2, 0, 0, 2, 0, - writeMutMetrics, conn, false, 0, 0, 0); + assertMutationTableMetrics(true, tableName, 1 + numAtomicUpserts, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * (numAtomicUpserts + 1), + true, 2, 0, 0, 2, 0, + writeMutMetrics, conn, false, + convertTimeInMsToNs(CLOCK_DELAY) * (numAtomicUpserts + 1), + convertTimeInMsToNs(CLOCK_DELAY) * (numAtomicUpserts + 1), + convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * (numAtomicUpserts + 1)); assertEquals(numAtomicUpserts, getMetricFromTableMetrics(tableName, ATOMIC_UPSERT_SQL_COUNTER)); assertTrue(getMetricFromTableMetrics(tableName, ATOMIC_UPSERT_COMMIT_TIME) > 0); } From 2bc4b0346d8e609da263fa44b5d486e20f7e2bb5 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Thu, 23 Jan 2025 14:24:16 +0530 Subject: [PATCH 3/9] Minor nits --- .gitignore | 1 - .../apache/phoenix/jdbc/PhoenixStatement.java | 23 ++++++++++++++----- .../phoenix/util/ManualEnvironmentEdge.java | 2 +- .../PhoenixTableLevelMetricsIT.java | 12 +++++----- 4 files changed, 24 insertions(+), 14 deletions(-) diff --git a/.gitignore b/.gitignore index bd215757262..bebe16f2800 100644 --- a/.gitignore +++ b/.gitignore @@ -35,4 +35,3 @@ phoenix-hbase-compat-1.5.0/ # Vim swap files .*.sw* -.codegenie diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java index 9ece871fe8f..d345548e743 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java @@ -43,6 +43,7 @@ import static org.apache.phoenix.monitoring.MetricType.UPSERT_SQL_COUNTER; import static org.apache.phoenix.monitoring.MetricType.UPSERT_SQL_QUERY_TIME; import static org.apache.phoenix.monitoring.MetricType.UPSERT_SUCCESS_SQL_COUNTER; +import static org.apache.phoenix.monitoring.MutationMetricQueue.MutationMetric; import java.io.File; import java.io.IOException; @@ -234,7 +235,6 @@ import org.apache.phoenix.util.ValidateLastDDLTimestampUtil; import org.slf4j.Logger; import org.slf4j.LoggerFactory; -import static org.apache.phoenix.monitoring.MutationMetricQueue.MutationMetric; import org.apache.phoenix.thirdparty.com.google.common.base.Throwables; import org.apache.phoenix.thirdparty.com.google.common.collect.ListMultimap; @@ -744,13 +744,13 @@ public Pair call() throws SQLException { } MutationMetric stagedMutationMetric; if (isUpsert) { - stagedMutationMetric = getStagedMutationMetric( + stagedMutationMetric = getUncommittedMutationMetric( mutationPlanCreationTimeInNs, mutationPlanExecutionTimeInNs, 0, 0, executeMutationTimeSpentInNs, 0); } else { - stagedMutationMetric = getStagedMutationMetric(0, 0, + stagedMutationMetric = getUncommittedMutationMetric(0, 0, mutationPlanCreationTimeInNs, mutationPlanExecutionTimeInNs, 0, executeMutationTimeSpentInNs); } @@ -798,9 +798,20 @@ public Pair call() throws SQLException { } } - private MutationMetric getStagedMutationMetric(long upsertMutationPlanCreationTime, long upsertMutationPlanExecutionTime, - long deleteMutationPlanCreationTime, long deleteMutationPlanExecutionTime, - long upsertExecuteMutationTime, long deleteExecuteMutationTime) { + /** + * Get mutation metrics for executeMutation call i.e. before the mutation are committed. + * All the times are in nano seconds. + * @param upsertMutationPlanCreationTime Time taken to create the upsert mutation plan. + * @param upsertMutationPlanExecutionTime Time taken to execute the upsert mutation plan. + * @param deleteMutationPlanCreationTime Time taken to create the delete mutation plan. + * @param deleteMutationPlanExecutionTime Time taken to execute the delete mutation plan. + * @param upsertExecuteMutationTime Time taken by upsert in executeMutation call. + * @param deleteExecuteMutationTime Time taken by delete in executeMutation call. + * @return MutationMetric object. + */ + private MutationMetric getUncommittedMutationMetric(long upsertMutationPlanCreationTime, long upsertMutationPlanExecutionTime, + long deleteMutationPlanCreationTime, long deleteMutationPlanExecutionTime, + long upsertExecuteMutationTime, long deleteExecuteMutationTime) { return new MutationMetric(0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, 0, upsertMutationPlanCreationTime, upsertMutationPlanExecutionTime, deleteMutationPlanCreationTime, deleteMutationPlanExecutionTime, upsertExecuteMutationTime, deleteExecuteMutationTime); diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java index 7029f3b975f..5c55d09b446 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java @@ -55,4 +55,4 @@ public void setValueInNs(long newValue) { public void incrementValueInNs(long newValue) { this.value += newValue; } -} \ No newline at end of file +} diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index b5d6b56833a..75f6926aa36 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -909,7 +909,9 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa writeMutMetrics = getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); - assertMutationTableMetrics(true, tableName, numRows, 0, 5 * delay * numRows, true, numRows, 0, 0, 1, + assertMutationTableMetrics(true, tableName, numRows, 0, + MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * delay * numRows, + true, numRows, 0, 0, 1, 0, writeMutMetrics, conn, true, convertTimeInMsToNs(delay) * numRows, convertTimeInMsToNs(delay) * numRows, @@ -1064,10 +1066,8 @@ private static void assertMetricValue(Metric m, MetricType checkType, long compa getWriteMetricInfoForMutationsSinceLastReset(conn).get(tableName); conn.close(); assertMutationTableMetrics(true, tableName, numRows, 0, - 0, - true, numRows, delayRs, 0, 1, - 0, writeMutMetrics, conn, true, - 0, 0, 0); + 0, true, numRows, delayRs, 0, 1, + 0, writeMutMetrics, conn, true, 0, 0, 0); } } @@ -1489,7 +1489,7 @@ public void testMetricsWithIndexUsage() throws Exception { assertMutationTableMetrics(true, tableName, 1 + numAtomicUpserts, 0, MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY * (numAtomicUpserts + 1), true, 2, 0, 0, 2, 0, - writeMutMetrics, conn, false, + writeMutMetrics, conn, false, convertTimeInMsToNs(CLOCK_DELAY) * (numAtomicUpserts + 1), convertTimeInMsToNs(CLOCK_DELAY) * (numAtomicUpserts + 1), convertTimeInMsToNs(MIN_CLOCK_DELAYS_IN_EXECUTE_MUTATION * CLOCK_DELAY) * (numAtomicUpserts + 1)); From cc4bf18c72995728ab17df9d4bd824990d6c5957 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Thu, 23 Jan 2025 20:44:29 +0530 Subject: [PATCH 4/9] Fix tests --- .../org/apache/phoenix/util/EnvironmentEdge.java | 12 +++++++++--- .../apache/phoenix/util/ManualEnvironmentEdge.java | 8 -------- .../monitoring/PhoenixTableLevelMetricsIT.java | 5 ----- 3 files changed, 9 insertions(+), 16 deletions(-) diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java index 2e0102337be..b4ce4a9092b 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java @@ -18,8 +18,6 @@ */ package org.apache.phoenix.util; -import org.apache.commons.lang3.NotImplementedException; - /** * Has some basic interaction with the environment. Alternate implementations * can be used where required (eg in tests). @@ -43,6 +41,14 @@ public abstract class EnvironmentEdge implements org.apache.hadoop.hbase.util.En * @return a time marker in nano seconds */ public long nanoTime() { - throw new NotImplementedException("Not Implemented!"); + return convertMsToNs(currentTime()); + } + + protected long convertMsToNs(long value) { + return value * 1000000; + } + + protected long convertNsToMs(long value) { + return value / 1000000; } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java index 5c55d09b446..5ae90e8b611 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java @@ -22,14 +22,6 @@ public class ManualEnvironmentEdge extends EnvironmentEdge { // value is in Nano seconds protected long value = 1L; - private long convertMsToNs(long value) { - return value * 1000000; - } - - private long convertNsToMs(long value) { - return value / 1000000; - } - public void setValue(long newValue) { value = convertMsToNs(newValue); } diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index 75f6926aa36..f5053611c6d 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -1671,11 +1671,6 @@ public MyClock(long time, long delay) { this.time.addAndGet(this.delay); return currentTime; } - - @Override - public long nanoTime() { - return convertTimeInMsToNs(currentTime()); - } } /** From 3e1be4f0bd72811ea2976e3b850cbc04cc2ee3a9 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Fri, 24 Jan 2025 12:57:13 +0530 Subject: [PATCH 5/9] Fix tests --- .../monitoring/BasePhoenixMetricsIT.java | 70 ++++++++++++++++++- .../monitoring/PhoenixLoggingMetricsIT.java | 2 +- .../phoenix/monitoring/PhoenixMetricsIT.java | 12 +++- 3 files changed, 80 insertions(+), 4 deletions(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java index 6be65afe5cd..f61f97b3796 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java @@ -115,7 +115,7 @@ static void assertMutationMetrics(String tableName, int numRows, boolean isUpser assertEquals("Table names didn't match!", tableName, t); Map p = entry.getValue(); - assertEquals("There should have been sixteen metrics", 16, p.size()); + assertEquals("There should have been sixteen metrics", 22, p.size()); boolean mutationBatchSizePresent = false; boolean mutationCommitTimePresent = false; @@ -132,6 +132,12 @@ static void assertMutationMetrics(String tableName, int numRows, boolean isUpser boolean upsertMutationSqlCounterPresent = false; boolean upsertCommitTimeCounterPresent = false; boolean deleteCommitTimeCounterPresent = false; + boolean upsertPlanCreationTimePresent = false; + boolean upsertPlanExecutionTimePresent = false; + boolean upsertExecuteMutationTimePresent = false; + boolean deletePlanCreationTimePresent = false; + boolean deletePlanExecutionTimePresent = false; + boolean deleteExecuteMutationTimePresent = false; for (Map.Entry metric : p.entrySet()) { MetricType metricType = metric.getKey(); long metricValue = metric.getValue(); @@ -206,6 +212,62 @@ static void assertMutationMetrics(String tableName, int numRows, boolean isUpser } deleteCommitTimeCounterPresent = true; } + else if (metricType.equals(MetricType.UPSERT_PLAN_CREATION_TIME)) { + if (isUpsert) { + assertTrue("Upsert plan creation time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero upsert plan creation time counter expected", 0, metricValue); + } + upsertPlanCreationTimePresent = true; + } + else if (metricType.equals(MetricType.UPSERT_PLAN_EXECUTION_TIME)) { + if (isUpsert) { + assertTrue("Upsert plan execution time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero upsert plan execution time counter expected", 0, metricValue); + } + upsertPlanExecutionTimePresent = true; + } + else if (metricType.equals(MetricType.UPSERT_EXECUTE_MUTATION_TIME)) { + if (isUpsert) { + assertTrue("Upsert execute mutation time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero upsert execute mutation time counter expected", 0, metricValue); + } + upsertExecuteMutationTimePresent = true; + } + else if (metricType.equals(MetricType.DELETE_PLAN_CREATION_TIME)) { + if (! isUpsert) { + assertTrue("Delete plan creation time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero delete plan creation time counter expected", 0, metricValue); + + } + deletePlanCreationTimePresent = true; + } + else if (metricType.equals(MetricType.DELETE_PLAN_EXECUTION_TIME)) { + if (! isUpsert) { + assertTrue("Delete plan execution time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero delete plan execution time counter expected", 0, metricValue); + + } + deletePlanExecutionTimePresent = true; + } + else if (metricType.equals(MetricType.DELETE_EXECUTE_MUTATION_TIME)) { + if (! isUpsert) { + assertTrue("Delete execute mutation time counter should be greater than zero", + metricValue > 0); + } else { + assertEquals("Zero delete execute mutation time counter expected", 0, metricValue); + } + deleteExecuteMutationTimePresent = true; + } } assertTrue(mutationBatchSizePresent); assertTrue(mutationCommitTimePresent); @@ -222,6 +284,12 @@ static void assertMutationMetrics(String tableName, int numRows, boolean isUpser assertTrue(deleteBatchFailedCounterPresent); assertTrue(upsertCommitTimeCounterPresent); assertTrue(deleteCommitTimeCounterPresent); + assertTrue(upsertPlanCreationTimePresent); + assertTrue(upsertPlanExecutionTimePresent); + assertTrue(upsertExecuteMutationTimePresent); + assertTrue(deletePlanCreationTimePresent); + assertTrue(deletePlanExecutionTimePresent); + assertTrue(deleteExecuteMutationTimePresent); } } diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java index 5691a8ca6b2..8d3cad30f34 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java @@ -157,7 +157,7 @@ public void testPhoenixMetricsLoggedOnClose() throws Exception { // Hence mutation metrics are not expected during connection close loggedConn.close(); assertTrue("Mutation write metrics are not logged for " + tableName2, - mutationWriteMetricsMap.size() == 0); + mutationWriteMetricsMap.size() > 0); assertTrue("Mutation read metrics for not found for " + tableName1, mutationReadMetricsMap.get(tableName1).size() > 0); assertReadMetricsForMutatingSql(tableName1, 1, mutationReadMetricsMap); diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java index 8c007df082f..edd149090c6 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java @@ -40,6 +40,9 @@ import static org.apache.phoenix.monitoring.GlobalClientMetrics.GLOBAL_TASK_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.COUNT_MILLS_BETWEEN_NEXTS; import static org.apache.phoenix.monitoring.MetricType.DELETE_COMMIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.DELETE_PLAN_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.MEMORY_CHUNK_BYTES; import static org.apache.phoenix.monitoring.MetricType.MUTATION_COMMIT_TIME; import static org.apache.phoenix.monitoring.MetricType.QUERY_TIMEOUT_COUNTER; @@ -48,6 +51,9 @@ import static org.apache.phoenix.monitoring.MetricType.TASK_EXECUTION_TIME; import static org.apache.phoenix.monitoring.MetricType.TASK_QUEUE_WAIT_TIME; import static org.apache.phoenix.monitoring.MetricType.UPSERT_COMMIT_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_EXECUTE_MUTATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_CREATION_TIME; +import static org.apache.phoenix.monitoring.MetricType.UPSERT_PLAN_EXECUTION_TIME; import static org.apache.phoenix.util.PhoenixRuntime.TENANT_ID_ATTRIB; import static org.apache.phoenix.util.PhoenixRuntime.UPSERT_BATCH_SIZE_ATTRIB; import static org.junit.Assert.assertEquals; @@ -133,7 +139,9 @@ public class PhoenixMetricsIT extends BasePhoenixMetricsIT { private static final String DELETE_ALL_DML = "DELETE FROM %s"; private static final List mutationMetricsToSkip = - Lists.newArrayList(MUTATION_COMMIT_TIME, UPSERT_COMMIT_TIME, DELETE_COMMIT_TIME); + Lists.newArrayList(MUTATION_COMMIT_TIME, UPSERT_COMMIT_TIME, DELETE_COMMIT_TIME, + UPSERT_PLAN_CREATION_TIME, UPSERT_PLAN_EXECUTION_TIME, UPSERT_EXECUTE_MUTATION_TIME, + DELETE_PLAN_CREATION_TIME, DELETE_PLAN_EXECUTION_TIME, DELETE_EXECUTE_MUTATION_TIME); private static final List readMetricsToSkip = Lists.newArrayList(TASK_QUEUE_WAIT_TIME, TASK_EXECUTION_TIME, TASK_END_TO_END_TIME, COUNT_MILLS_BETWEEN_NEXTS); @@ -487,7 +495,7 @@ public void testMetricsForUpsert() throws Exception { String t = entry.getKey(); assertEquals("Table names didn't match!", tableName, t); Map p = entry.getValue(); - assertEquals("There should have been sixteen metrics", 16, p.size()); + assertEquals("There should have been sixteen metrics", 22, p.size()); boolean mutationBatchSizePresent = false; boolean mutationCommitTimePresent = false; boolean mutationBytesPresent = false; From 089f7b0cf710896a62bedd92faf7484a073043f5 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Wed, 29 Jan 2025 12:06:23 +0530 Subject: [PATCH 6/9] Address David's comments --- .../org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java | 2 +- .../apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java | 4 ++-- .../java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java | 2 +- 3 files changed, 4 insertions(+), 4 deletions(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java index f61f97b3796..0a0746e3fb6 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/BasePhoenixMetricsIT.java @@ -115,7 +115,7 @@ static void assertMutationMetrics(String tableName, int numRows, boolean isUpser assertEquals("Table names didn't match!", tableName, t); Map p = entry.getValue(); - assertEquals("There should have been sixteen metrics", 22, p.size()); + assertEquals("There should have been 22 metrics", 22, p.size()); boolean mutationBatchSizePresent = false; boolean mutationCommitTimePresent = false; diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java index 8d3cad30f34..07aba3f43eb 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java @@ -156,9 +156,9 @@ public void testPhoenixMetricsLoggedOnClose() throws Exception { // Autocommit is turned off by default // Hence mutation metrics are not expected during connection close loggedConn.close(); - assertTrue("Mutation write metrics are not logged for " + tableName2, + assertTrue("Mutation write metrics should be logged for " + tableName2, mutationWriteMetricsMap.size() > 0); - assertTrue("Mutation read metrics for not found for " + tableName1, + assertTrue("Mutation read metrics not found for " + tableName1, mutationReadMetricsMap.get(tableName1).size() > 0); assertReadMetricsForMutatingSql(tableName1, 1, mutationReadMetricsMap); diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java index edd149090c6..bea800a0a1f 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixMetricsIT.java @@ -495,7 +495,7 @@ public void testMetricsForUpsert() throws Exception { String t = entry.getKey(); assertEquals("Table names didn't match!", tableName, t); Map p = entry.getValue(); - assertEquals("There should have been sixteen metrics", 22, p.size()); + assertEquals("There should have been 22 metrics", 22, p.size()); boolean mutationBatchSizePresent = false; boolean mutationCommitTimePresent = false; boolean mutationBytesPresent = false; From f28a7682514db8f5d876a1ba213d0216162f5cc8 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Wed, 29 Jan 2025 12:16:23 +0530 Subject: [PATCH 7/9] Extension of David's comments --- .../phoenix/monitoring/PhoenixTableLevelMetricsIT.java | 9 ++++++++- 1 file changed, 8 insertions(+), 1 deletion(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index f5053611c6d..a14f946d109 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -345,7 +345,14 @@ static void assertSelectQueryTableMetrics(final String tableName, final boolean * @param writeMutMetrics write mutation metrics object * @param conn connection object. Note: this method must be called after connection close * since that's where we populate table-level write metrics - */ + * @param expectedSystemCatalogMetric True if metrics for calls to SYSTEM.CATALOG table were captured + * and should be validated + * @param expectedMinMutationPlanCreationTime minimum expected time taken to create mutation plan + * @param expectedMinMutationPlanExecutionTime minimum expected time taken to execute mutation plan + * @param expectedMinExecuteMutationTime minimum expected time taken by executeMutation() call + * + * @throws SQLException + */ private static void assertMutationTableMetrics(final boolean isUpsert, final String tableName, final long expectedUpsertOrDeleteSuccessSqlCt, final long expectedUpsertOrDeleteFailedSqlCt, From 112015067e6d2bafe50c690a1924f179cff6cd89 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Wed, 29 Jan 2025 12:18:46 +0530 Subject: [PATCH 8/9] Address David's comments --- .../org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java | 2 -- 1 file changed, 2 deletions(-) diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java index 07aba3f43eb..315ec71ce32 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixLoggingMetricsIT.java @@ -153,8 +153,6 @@ public void testPhoenixMetricsLoggedOnClose() throws Exception { String upsertSelect = "UPSERT INTO " + tableName2 + " SELECT * FROM " + tableName1; loggedConn.createStatement().executeUpdate(upsertSelect); - // Autocommit is turned off by default - // Hence mutation metrics are not expected during connection close loggedConn.close(); assertTrue("Mutation write metrics should be logged for " + tableName2, mutationWriteMetricsMap.size() > 0); From 36ee9d45b5015d3a8a23d9b7bfd98d263ee62225 Mon Sep 17 00:00:00 2001 From: Sanjeet Malhotra Date: Wed, 29 Jan 2025 12:44:29 +0530 Subject: [PATCH 9/9] Address David's comments --- .../java/org/apache/phoenix/jdbc/PhoenixStatement.java | 3 ++- .../java/org/apache/phoenix/util/EnvironmentEdge.java | 6 +++--- .../org/apache/phoenix/util/ManualEnvironmentEdge.java | 6 +++--- .../main/java/org/apache/phoenix/util/PhoenixRuntime.java | 8 -------- .../phoenix/monitoring/PhoenixTableLevelMetricsIT.java | 2 +- 5 files changed, 9 insertions(+), 16 deletions(-) diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java index d345548e743..484e53e5b96 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/jdbc/PhoenixStatement.java @@ -222,6 +222,7 @@ import org.apache.phoenix.util.ClientUtil; import org.apache.phoenix.util.CDCUtil; import org.apache.phoenix.util.CursorUtil; +import org.apache.phoenix.util.EnvironmentEdge; import org.apache.phoenix.util.PhoenixKeyValueUtil; import org.apache.phoenix.util.EnvironmentEdgeManager; import org.apache.phoenix.util.LogUtil; @@ -730,7 +731,7 @@ public Pair call() throws SQLException { long executeMutationTimeSpentInNs = EnvironmentEdgeManager.timeMarkerInNanos() - startExecuteMutationTime; // This will ensure existing use cases of metrics are not broken. - long executeMutationTimeSpent = PhoenixRuntime.convertTimeInNsToMs(executeMutationTimeSpentInNs); + long executeMutationTimeSpent = EnvironmentEdge.convertTimeInNsToMs(executeMutationTimeSpentInNs); TableMetricsManager.updateMetricsMethod(tableName, isUpsert ? UPSERT_SQL_COUNTER : DELETE_SQL_COUNTER, 1); diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java index b4ce4a9092b..d24d842c6e8 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/EnvironmentEdge.java @@ -41,14 +41,14 @@ public abstract class EnvironmentEdge implements org.apache.hadoop.hbase.util.En * @return a time marker in nano seconds */ public long nanoTime() { - return convertMsToNs(currentTime()); + return convertTimeInMsToNs(currentTime()); } - protected long convertMsToNs(long value) { + public static long convertTimeInMsToNs(long value) { return value * 1000000; } - protected long convertNsToMs(long value) { + public static long convertTimeInNsToMs(long value) { return value / 1000000; } } diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java index 5ae90e8b611..ca5079621af 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/ManualEnvironmentEdge.java @@ -23,16 +23,16 @@ public class ManualEnvironmentEdge extends EnvironmentEdge { protected long value = 1L; public void setValue(long newValue) { - value = convertMsToNs(newValue); + value = convertTimeInMsToNs(newValue); } public void incrementValue(long addedValue) { - value += convertMsToNs(addedValue); + value += convertTimeInMsToNs(addedValue); } @Override public long currentTime() { - return convertNsToMs(this.value); + return convertTimeInNsToMs(this.value); } @Override diff --git a/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java b/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java index 10d15b462cc..88ad2e36eff 100644 --- a/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java +++ b/phoenix-core-client/src/main/java/org/apache/phoenix/util/PhoenixRuntime.java @@ -1660,12 +1660,4 @@ public static long getCurrentScn(ReadOnlyProps props) { String scn = props.get(CURRENT_SCN_ATTRIB); return scn != null ? Long.parseLong(scn) : HConstants.LATEST_TIMESTAMP; } - - public static long convertTimeInNsToMs(long value) { - return value / 1000000; - } - - public static long convertTimeInMsToNs(long value) { - return value * 1000000; - } } diff --git a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java index a14f946d109..1b1e6480064 100644 --- a/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java +++ b/phoenix-core/src/it/java/org/apache/phoenix/monitoring/PhoenixTableLevelMetricsIT.java @@ -124,13 +124,13 @@ import static org.apache.phoenix.monitoring.PhoenixMetricsIT.doPointDeleteFromTable; import static org.apache.phoenix.monitoring.PhoenixMetricsIT.doDeleteAllFromTable; import static org.apache.phoenix.util.DelayedOrFailingRegionServer.INJECTED_EXCEPTION_STRING; +import static org.apache.phoenix.util.EnvironmentEdge.convertTimeInMsToNs; import static org.apache.phoenix.util.PhoenixRuntime.JDBC_PROTOCOL_SEPARATOR; import static org.apache.phoenix.util.PhoenixRuntime.clearTableLevelMetrics; import static org.apache.phoenix.util.PhoenixRuntime.getOverAllReadRequestMetricInfo; import static org.apache.phoenix.util.PhoenixRuntime.getPhoenixTableClientMetrics; import static org.apache.phoenix.util.PhoenixRuntime.getRequestReadMetricInfo; import static org.apache.phoenix.util.PhoenixRuntime.getWriteMetricInfoForMutationsSinceLastReset; -import static org.apache.phoenix.util.PhoenixRuntime.convertTimeInMsToNs; import static org.junit.Assert.assertEquals; import static org.junit.Assert.assertFalse; import static org.junit.Assert.assertNotNull;