This is an automated email from the ASF dual-hosted git repository. mblow pushed a commit to branch master in repository https://gitbox.apache.org/repos/asf/asterixdb.git
commit 55743604d475c5d993731f81684067344c6e0c19 Author: Ali Alsuliman <[email protected]> AuthorDate: Thu May 22 17:02:05 2025 -0700 [NO ISSUE][OTH] query/job logs changes - user model changes: no - storage format changes: no - interface changes: no Details: - log job running/release at info. - log and redact query statement parameters. - reduce some logs to trace. Ext-ref: MB-66663 Change-Id: I67ae0dee5ca79bb03b982842f0b1a3f99e705905 Reviewed-on: https://asterix-gerrit.ics.uci.edu/c/asterixdb/+/19731 Tested-by: Jenkins <[email protected]> Reviewed-by: Ali Alsuliman <[email protected]> Reviewed-by: Ian Maxon <[email protected]> Reviewed-by: Michael Blow <[email protected]> --- .../api/http/server/NCQueryServiceServlet.java | 11 +++-- .../http/server/QueryServiceRequestParameters.java | 9 ++-- .../apache/hyracks/control/cc/job/JobManager.java | 7 +-- .../VariableDeletableTupleMemoryManager.java | 4 +- .../std/group/HashSpillableTableFactory.java | 12 ++--- .../OptimizedHybridHashJoinOperatorDescriptor.java | 54 ++++++++-------------- .../std/sort/AbstractExternalSortRunMerger.java | 13 ++---- 7 files changed, 44 insertions(+), 66 deletions(-) diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java index 9fa479c398..54fb852050 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/NCQueryServiceServlet.java @@ -97,13 +97,15 @@ public class NCQueryServiceServlet extends QueryServiceServlet { try { responseMsg = (ExecuteStatementResponseMessage) responseFuture.get(timeout, TimeUnit.MILLISECONDS); } catch (InterruptedException e) { - cancelQuery(ncMb, ncCtx.getNodeId(), requestReference.getUuid(), param.getClientContextID(), e, false); + cancelQuery(ncMb, ncCtx.getNodeId(), requestReference.getUuid(), param.getClientContextID(), e, false, + "interrupt"); throw e; } catch (TimeoutException exception) { RuntimeDataException hde = new RuntimeDataException(ErrorCode.REQUEST_TIMEOUT); hde.addSuppressed(exception); // cancel query - cancelQuery(ncMb, ncCtx.getNodeId(), requestReference.getUuid(), param.getClientContextID(), hde, true); + cancelQuery(ncMb, ncCtx.getNodeId(), requestReference.getUuid(), param.getClientContextID(), hde, true, + "timeout"); throw hde; } executionState.end(); @@ -156,7 +158,7 @@ public class NCQueryServiceServlet extends QueryServiceServlet { } private void cancelQuery(INCMessageBroker messageBroker, String nodeId, String uuid, String clientContextID, - Exception exception, boolean wait) { + Exception exception, boolean wait, String reason) { if (uuid == null && clientContextID == null) { return; } @@ -165,8 +167,7 @@ public class NCQueryServiceServlet extends QueryServiceServlet { CancelQueryRequest cancelQueryMessage = new CancelQueryRequest(nodeId, cancelQueryFuture.getFutureId(), uuid, clientContextID); // TODO(mblow): multicc -- need to send cancellation to the correct cc - LOGGER.info("Cancelling query with uuid:{}, clientContextID:{} due to {}", uuid, clientContextID, - exception.getClass().getSimpleName()); + LOGGER.info("Cancelling query with uuid:{}, clientContextID:{} due to {}", uuid, clientContextID, reason); messageBroker.sendMessageToPrimaryCC(cancelQueryMessage); if (wait) { cancelQueryFuture.get(ExecuteStatementRequestMessage.DEFAULT_QUERY_CANCELLATION_WAIT_MILLIS, diff --git a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java index 563f49864f..ed47832196 100644 --- a/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java +++ b/asterixdb/asterix-app/src/main/java/org/apache/asterix/api/http/server/QueryServiceRequestParameters.java @@ -19,8 +19,6 @@ package org.apache.asterix.api.http.server; -import static org.apache.asterix.utils.RedactionUtil.REDACTED_SENSITIVE_ENTRY_VALUE; - import java.io.IOException; import java.util.HashMap; import java.util.Iterator; @@ -428,7 +426,12 @@ public class QueryServiceRequestParameters { object.put("source", source); if (statementParams != null) { for (Map.Entry<String, JsonNode> statementParam : statementParams.entrySet()) { - object.set('$' + statementParam.getKey(), REDACTED_SENSITIVE_ENTRY_VALUE); + try { + String s = OBJECT_MAPPER.writeValueAsString(statementParam.getValue()); + object.put('$' + statementParam.getKey(), LogRedactionUtil.userData(s)); + } catch (JsonProcessingException e) { + // ignore + } } } return object; diff --git a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/job/JobManager.java b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/job/JobManager.java index d803c88fb3..36c03d796d 100644 --- a/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/job/JobManager.java +++ b/hyracks-fullstack/hyracks/hyracks-control/hyracks-control-cc/src/main/java/org/apache/hyracks/control/cc/job/JobManager.java @@ -316,7 +316,7 @@ public class JobManager implements IJobManager { run.setStartTime(System.currentTimeMillis()); run.setStartTimeZoneId(ZoneId.systemDefault().getId()); JobId jobId = run.getJobId(); - logJobCapacity(run, "running", Level.DEBUG); + logJobCapacity(run, "running", Level.INFO); activeRunMap.put(jobId, run); run.setStatus(JobStatus.RUNNING, null); executeJobInternal(run); @@ -360,7 +360,7 @@ public class JobManager implements IJobManager { private void releaseJobCapacity(JobRun jobRun) { final JobSpecification job = jobRun.getJobSpecification(); jobCapacityController.release(job); - logJobCapacity(jobRun, "released", Level.DEBUG); + logJobCapacity(jobRun, "released", Level.INFO); } private void logJobCapacity(JobRun jobRun, String jobStateDesc, Level lvl) { @@ -374,7 +374,8 @@ public class JobManager implements IJobManager { return; } IReadOnlyClusterCapacity clusterCapacity = jobCapacityController.getClusterCapacity(); - LOGGER.log(lvl, "{} {}, memory={}, cpu={}, (new) cluster memory={}, cpu={}, currently running={}, queued={}", + LOGGER.log(lvl, + "{} {}, job memory={}, cpu={}, (new) cluster memory={}, cpu={}, currently running={}, queued={}", jobStateDesc, jobRun.getJobId(), requiredMemory, requiredCPUs, clusterCapacity.getAggregatedMemoryByteSize(), clusterCapacity.getAggregatedCores(), getRunningJobsCount(), jobQueue.size()); diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/buffermanager/VariableDeletableTupleMemoryManager.java b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/buffermanager/VariableDeletableTupleMemoryManager.java index b053cac66b..40ff2e4d16 100644 --- a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/buffermanager/VariableDeletableTupleMemoryManager.java +++ b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/buffermanager/VariableDeletableTupleMemoryManager.java @@ -161,9 +161,7 @@ public class VariableDeletableTupleMemoryManager implements IDeletableTupleBuffe policy.close(); frames.clear(); numTuples = 0; - if (LOG.isDebugEnabled()) { - LOG.debug("VariableTupleMemoryManager has reorganized " + statsReOrg + " times"); - } + LOG.trace("VariableTupleMemoryManager has reorganized {} times", statsReOrg); statsReOrg = 0; } diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/group/HashSpillableTableFactory.java b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/group/HashSpillableTableFactory.java index 1e5c121f7d..2f2153b0eb 100644 --- a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/group/HashSpillableTableFactory.java +++ b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/group/HashSpillableTableFactory.java @@ -131,10 +131,8 @@ public class HashSpillableTableFactory implements ISpillableTableFactory { final int numPartitions = getNumOfPartitions(inputDataBytesSize / ctx.getInitialFrameSize(), memoryBudget); final int entriesPerPartition = (int) Math.ceil(1.0 * tableSize / numPartitions); - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("created hashtable, table size:" + tableSize + " file size:" + inputDataBytesSize - + " #partitions:" + numPartitions); - } + LOGGER.trace("created hashtable, table size:{} file size:{} #partitions:{}", tableSize, inputDataBytesSize, + numPartitions); final ArrayTupleBuilder outputTupleBuilder = new ArrayTupleBuilder(outRecordDescriptor.getFields().length); @@ -185,10 +183,8 @@ public class HashSpillableTableFactory implements ISpillableTableFactory { if (force || hashTableForTuplePointer.isGarbageCollectionNeeded()) { int numberOfFramesReclaimed = hashTableForTuplePointer.collectGarbage(bufferAccessor, tpcIntermediate); - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("Garbage Collection on Hash table is done. Deallocated frames:" - + numberOfFramesReclaimed); - } + LOGGER.trace("Garbage Collection on Hash table is done. Deallocated frames:{}", + numberOfFramesReclaimed); return numberOfFramesReclaimed != -1; } return false; diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/join/OptimizedHybridHashJoinOperatorDescriptor.java b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/join/OptimizedHybridHashJoinOperatorDescriptor.java index 0f31491feb..6fc9124451 100644 --- a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/join/OptimizedHybridHashJoinOperatorDescriptor.java +++ b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/join/OptimizedHybridHashJoinOperatorDescriptor.java @@ -490,12 +490,10 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD long probePartSize = (long) Math.ceil((double) probeSideReader.getFileSize() / (double) frameSize); int beforeMax = Math.max(buildSizeInTuple, probeSizeInTuple); - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\n>>>Joining Partition Pairs (thread_id " + Thread.currentThread().getId() - + ") (pid " + ") - (level " + level + ")" + " - BuildSize:\t" + buildPartSize - + "\tProbeSize:\t" + probePartSize + " - MemForJoin " + (state.memForJoin) - + " - LeftOuter is " + isLeftOuter); - } + LOGGER.trace( + "\n>>>Joining Partition Pairs (thread_id {}) (pid ) - (level {}) - BuildSize:\t{}\tProbeSize:\t{} - MemForJoin {} - LeftOuter is {}", + Thread.currentThread().getId(), level, buildPartSize, probePartSize, state.memForJoin, + isLeftOuter); // Calculate the expected hash table size for the both side. long expectedHashTableSizeForBuildInFrame = @@ -511,10 +509,8 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD int tabSize = -1; if (!forceRoleReversal && (isLeftOuter || (buildPartSize < probePartSize))) { //Case 1.1 - InMemHJ (without Role-Reversal) - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\t>>>Case 1.1 (IsLeftOuter || buildSize<probe) AND ApplyInMemHJ - [Level " - + level + "]"); - } + LOGGER.trace("\t>>>Case 1.1 (IsLeftOuter || buildSize<probe) AND ApplyInMemHJ - [Level {}]", + level); tabSize = buildSizeInTuple; if (tabSize == 0) { throw new HyracksDataException( @@ -524,10 +520,9 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD applyInMemHashJoin(buildKeys, probeKeys, tabSize, buildRd, probeRd, buildHpc, probeHpc, buildSideReader, probeSideReader, probComp); // checked-confirmed } else { //Case 1.2 - InMemHJ with Role Reversal - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\t>>>Case 1.2. (NoIsLeftOuter || probe<build) AND ApplyInMemHJ" - + "WITH RoleReversal - [Level " + level + "]"); - } + LOGGER.trace( + "\t>>>Case 1.2. (NoIsLeftOuter || probe<build) AND ApplyInMemHJWITH RoleReversal - [Level {}]", + level); tabSize = probeSizeInTuple; if (tabSize == 0) { throw new HyracksDataException( @@ -540,25 +535,18 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD } //Apply (Recursive) HHJ else { - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\t>>>Case 2. ApplyRecursiveHHJ - [Level " + level + "]"); - } + LOGGER.trace("\t>>>Case 2. ApplyRecursiveHHJ - [Level {}]", level); if (!forceRoleReversal && (isLeftOuter || buildPartSize < probePartSize)) { //Case 2.1 - Recursive HHJ (without Role-Reversal) - if (LOGGER.isDebugEnabled()) { - LOGGER.debug( - "\t\t>>>Case 2.1 - RecursiveHHJ WITH (isLeftOuter || build<probe) - [Level " - + level + "]"); - } + LOGGER.trace( + "\t\t>>>Case 2.1 - RecursiveHHJ WITH (isLeftOuter || build<probe) - [Level {}]", + level); applyHybridHashJoin((int) buildPartSize, PROBE_REL, BUILD_REL, probeKeys, buildKeys, probeRd, buildRd, probeHpc, buildHpc, probeSideReader, buildSideReader, level, beforeMax, probComp); } else { //Case 2.2 - Recursive HHJ (with Role-Reversal) - if (LOGGER.isDebugEnabled()) { - LOGGER.debug( - "\t\t>>>Case 2.2. - RecursiveHHJ WITH RoleReversal - [Level " + level + "]"); - } + LOGGER.trace("\t\t>>>Case 2.2. - RecursiveHHJ WITH RoleReversal - [Level {}]", level); applyHybridHashJoin((int) probePartSize, BUILD_REL, PROBE_REL, buildKeys, probeKeys, buildRd, probeRd, buildHpc, probeHpc, buildSideReader, probeSideReader, level, @@ -624,10 +612,9 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD BitSet rPStatus = rHHj.getPartitionStatus(); if (!forceNLJ && (afterMax < (NLJ_SWITCH_THRESHOLD * beforeMax))) { //Case 2.1.1 - Keep applying HHJ - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\t\t>>>Case 2.1.1 - KEEP APPLYING RecursiveHHJ WITH " - + "(isLeftOuter || build<probe) - [Level " + level + "]"); - } + LOGGER.trace( + "\t\t>>>Case 2.1.1 - KEEP APPLYING RecursiveHHJ WITH (isLeftOuter || build<probe) - [Level {}]", + level); for (int rPid = rPStatus.nextSetBit(0); rPid >= 0; rPid = rPStatus.nextSetBit(rPid + 1)) { RunFileReader rbrfw = rHHj.getBuildRFReader(rPid); RunFileReader rprfw = rHHj.getProbeRFReader(rPid); @@ -656,10 +643,9 @@ public class OptimizedHybridHashJoinOperatorDescriptor extends AbstractOperatorD } } else { //Case 2.1.2 - Switch to NLJ - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("\t\t>>>Case 2.1.2 - SWITCHED to NLJ RecursiveHHJ WITH " - + "(isLeftOuter || build<probe) - [Level " + level + "]"); - } + LOGGER.trace( + "\t\t>>>Case 2.1.2 - SWITCHED to NLJ RecursiveHHJ WITH (isLeftOuter || build<probe) - [Level {}]", + level); for (int rPid = rPStatus.nextSetBit(0); rPid >= 0; rPid = rPStatus.nextSetBit(rPid + 1)) { RunFileReader rbrfw = rHHj.getBuildRFReader(rPid); RunFileReader rprfw = rHHj.getProbeRFReader(rPid); diff --git a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/sort/AbstractExternalSortRunMerger.java b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/sort/AbstractExternalSortRunMerger.java index 1beaab8ac4..e573c1c677 100644 --- a/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/sort/AbstractExternalSortRunMerger.java +++ b/hyracks-fullstack/hyracks/hyracks-dataflow-std/src/main/java/org/apache/hyracks/dataflow/std/sort/AbstractExternalSortRunMerger.java @@ -117,19 +117,14 @@ public abstract class AbstractExternalSortRunMerger { if (currentGenerationRunAvailable.isEmpty()) { numberOfPasses++; - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("generated runs:" + stop); - } + LOGGER.trace("generated runs: {}", stop); runs.subList(0, stop).clear(); currentGenerationRunAvailable.clear(); currentGenerationRunAvailable.set(0, runs.size()); stop = runs.size(); } } else { - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("final runs: {}", stop); - LOGGER.debug("number of passes: " + numberOfPasses); - } + LOGGER.trace("final runs: {}, number of passes: {}", stop, numberOfPasses); merge(finalWriter, partialRuns); break; } @@ -206,9 +201,7 @@ public abstract class AbstractExternalSortRunMerger { } } finally { merger.close(); - if (LOGGER.isDebugEnabled()) { - LOGGER.debug("Output " + io + " frames"); - } + LOGGER.trace("Output {} frames", io); } }
