Skip to content

Commit 8bfa5fc

Browse files
committed
CNDN-16237: Add execution info to logs about aborted queries
1 parent d16a226 commit 8bfa5fc

File tree

2 files changed

+433
-31
lines changed

2 files changed

+433
-31
lines changed

src/java/org/apache/cassandra/db/monitoring/MonitoringTask.java

Lines changed: 19 additions & 31 deletions
Original file line numberDiff line numberDiff line change
@@ -318,13 +318,17 @@ protected abstract static class Operation
318318
* this is set lazily as it takes time to build the query CQL */
319319
private String name;
320320

321+
/** Any specific execution info of the slowest operation among the aggregated operations. */
322+
protected Monitorable.ExecutionInfo slowestOperationExecutionInfo;
323+
321324
Operation(Monitorable operation, long nowNanos)
322325
{
323326
this.operation = operation;
324327
numTimesReported = 1;
325328
totalTimeNanos = nowNanos - operation.creationTimeNanos();
326329
minTime = totalTimeNanos;
327330
maxTime = totalTimeNanos;
331+
slowestOperationExecutionInfo = operation.executionInfo();
328332
}
329333

330334
public String name()
@@ -334,17 +338,24 @@ public String name()
334338
return name;
335339
}
336340

337-
void add(Operation operation)
341+
private void add(Operation operation)
338342
{
339343
numTimesReported++;
340344
totalTimeNanos += operation.totalTimeNanos;
345+
346+
if (operation.maxTime > maxTime)
347+
slowestOperationExecutionInfo = operation.executionInfo();
348+
341349
maxTime = Math.max(maxTime, operation.maxTime);
342350
minTime = Math.min(minTime, operation.minTime);
343351
}
344352

345353
public abstract String getLogMessage();
346354

347-
protected abstract Monitorable.ExecutionInfo executionInfo();
355+
protected Monitorable.ExecutionInfo executionInfo()
356+
{
357+
return slowestOperationExecutionInfo;
358+
}
348359
}
349360

350361
/**
@@ -360,26 +371,22 @@ private final static class FailedOperation extends Operation
360371
public String getLogMessage()
361372
{
362373
if (numTimesReported == 1)
363-
return String.format("<%s>, total time %d msec, timeout %d %s",
374+
return String.format("<%s>, total time %d msec, timeout %d %s%s",
364375
name(),
365376
NANOSECONDS.toMillis(totalTimeNanos),
366377
NANOSECONDS.toMillis(operation.timeoutNanos()),
367-
operation.isCrossNode() ? "msec/cross-node" : "msec");
378+
operation.isCrossNode() ? "msec/cross-node" : "msec",
379+
slowestOperationExecutionInfo.toLogString(true));
368380
else
369-
return String.format("<%s> timed out %d times, avg/min/max %d/%d/%d msec, timeout %d %s",
381+
return String.format("<%s> timed out %d times, avg/min/max %d/%d/%d msec, timeout %d %s%s",
370382
name(),
371383
numTimesReported,
372384
NANOSECONDS.toMillis(totalTimeNanos / numTimesReported),
373385
NANOSECONDS.toMillis(minTime),
374386
NANOSECONDS.toMillis(maxTime),
375387
NANOSECONDS.toMillis(operation.timeoutNanos()),
376-
operation.isCrossNode() ? "msec/cross-node" : "msec");
377-
}
378-
379-
@Override
380-
protected Monitorable.ExecutionInfo executionInfo()
381-
{
382-
return Monitorable.ExecutionInfo.EMPTY;
388+
operation.isCrossNode() ? "msec/cross-node" : "msec",
389+
slowestOperationExecutionInfo.toLogString(false));
383390
}
384391
}
385392

@@ -389,14 +396,10 @@ protected Monitorable.ExecutionInfo executionInfo()
389396
@VisibleForTesting
390397
public final static class SlowOperation extends Operation
391398
{
392-
/** Any specific execution info of the slowest operation among the aggregated operations. */
393-
private Monitorable.ExecutionInfo slowestOperationExecutionInfo;
394-
395399
@VisibleForTesting
396400
public SlowOperation(Monitorable operation, long slowAtNanos)
397401
{
398402
super(operation, slowAtNanos);
399-
slowestOperationExecutionInfo = operation.executionInfo();
400403
}
401404

402405
public String getLogMessage()
@@ -419,20 +422,5 @@ public String getLogMessage()
419422
operation.isCrossNode() ? "msec/cross-node" : "msec",
420423
slowestOperationExecutionInfo.toLogString(false));
421424
}
422-
423-
@Override
424-
protected Monitorable.ExecutionInfo executionInfo()
425-
{
426-
return slowestOperationExecutionInfo;
427-
}
428-
429-
@Override
430-
void add(Operation operation)
431-
{
432-
if (operation.maxTime > maxTime)
433-
slowestOperationExecutionInfo = operation.executionInfo();
434-
435-
super.add(operation);
436-
}
437425
}
438426
}

0 commit comments

Comments
 (0)