Slightly more detailed negative allocation logging

Hopefully will help debug #1739. Maybe.
This commit is contained in:
Jonathan Coates 2024-03-10 11:26:36 +00:00
parent a9191a4d4e
commit 3b8813cf8f
No known key found for this signature in database
GPG Key ID: B9E431FF07C98D06
1 changed files with 16 additions and 5 deletions

View File

@ -518,6 +518,7 @@ private void checkRunners(long[] workerThreadIds) {
} else {
allocations = null;
}
var allocationTime = System.nanoTime();
for (var i = 0; i < workers.length; i++) {
var runner = workers[i];
@ -532,7 +533,7 @@ private void checkRunners(long[] workerThreadIds) {
// And track the allocated memory.
if (allocations != null) {
executor.updateAllocations(new ThreadAllocation(workerThreadIds[i], allocations[i]));
executor.updateAllocations(new ThreadAllocation(workerThreadIds[i], allocations[i], allocationTime));
}
// If we're still within normal execution times (TIMEOUT) or soft abort (ABORT_TIMEOUT),
@ -814,7 +815,7 @@ void beforeWork() {
if (ThreadAllocations.isSupported()) {
var current = Thread.currentThread().getId();
THREAD_ALLOCATION.set(this, new ThreadAllocation(current, ThreadAllocations.getAllocatedBytes(current)));
THREAD_ALLOCATION.set(this, new ThreadAllocation(current, ThreadAllocations.getAllocatedBytes(current), System.nanoTime()));
}
}
@ -832,11 +833,20 @@ boolean afterWork() {
var info = THREAD_ALLOCATION.getAndSet(this, null);
assert info.threadId() == current;
var allocated = ThreadAllocations.getAllocatedBytes(current) - info.allocatedBytes();
var allocatedTotal = ThreadAllocations.getAllocatedBytes(current);
var allocated = allocatedTotal - info.allocatedBytes();
if (allocated > 0) {
metrics.observe(Metrics.JAVA_ALLOCATION, allocated);
} else if (allocated < 0) {
LOG.warn("Allocated a negative number of bytes ({})!", allocated);
LOG.warn(
"""
Allocated a negative number of bytes ({})!
Previous measurement at t={} on Thread #{} = {}
Current measurement at t={} on Thread #{} = {}""",
allocated,
info.time(), info.threadId(), info.allocatedBytes(),
System.nanoTime(), current, allocatedTotal
);
}
}
@ -901,7 +911,8 @@ protected boolean shouldPause() {
*
* @param threadId The ID of this thread.
* @param allocatedBytes The amount of memory this thread has allocated.
* @param time The time (in nanoseconds) when this time was computed.
*/
private record ThreadAllocation(long threadId, long allocatedBytes) {
private record ThreadAllocation(long threadId, long allocatedBytes, long time) {
}
}