You are viewing a plain text version of this content. The canonical link for it is here.
Posted to commits@arrow.apache.org by li...@apache.org on 2022/07/06 13:37:06 UTC
[arrow] branch master updated: ARROW-15958: [Java][Docs] Improve and document StackTrace (#12656)
This is an automated email from the ASF dual-hosted git repository.
lidavidm pushed a commit to branch master
in repository https://gitbox.apache.org/repos/asf/arrow.git
The following commit(s) were added to refs/heads/master by this push:
new 2d47a3cf0c ARROW-15958: [Java][Docs] Improve and document StackTrace (#12656)
2d47a3cf0c is described below
commit 2d47a3cf0c7f9afcbf262581fa6552dff62a9798
Author: David Li <li...@gmail.com>
AuthorDate: Wed Jul 6 09:36:59 2022 -0400
ARROW-15958: [Java][Docs] Improve and document StackTrace (#12656)
This can be useful to identify the origin of a leaked buffer.
While there's a "public" API, it wasn't actually usable because it has a parameter of package-private type. This adds an overload that doesn't take that parameter so the API is actually usable.
Authored-by: David Li <li...@gmail.com>
Signed-off-by: David Li <li...@gmail.com>
---
docs/source/java/memory.rst | 114 ++++++++++++++++++++-
.../java/org/apache/arrow/memory/ArrowBuf.java | 14 ++-
.../org/apache/arrow/memory/util/StackTrace.java | 4 +-
.../java/org/apache/arrow/util/TestStackTrace.java | 43 ++++++++
4 files changed, 167 insertions(+), 8 deletions(-)
diff --git a/docs/source/java/memory.rst b/docs/source/java/memory.rst
index 118f182f3c..23fa30e134 100644
--- a/docs/source/java/memory.rst
+++ b/docs/source/java/memory.rst
@@ -134,7 +134,7 @@ When enabled, a log will be kept of allocations.
Arrow logs some allocation information via SLF4J; configure it properly to see these logs (e.g. via Logback/Apache Log4j).
-Consider the following example to see how debug enabled help us with the tracking of allocators:
+Consider the following example to see how it helps us with the tracking of allocators:
.. code-block:: Java
@@ -142,12 +142,12 @@ Consider the following example to see how debug enabled help us with the trackin
import org.apache.arrow.memory.BufferAllocator;
import org.apache.arrow.memory.RootAllocator;
- try(BufferAllocator bufferAllocator = new RootAllocator(8 * 1024)){
+ try (BufferAllocator bufferAllocator = new RootAllocator(8 * 1024)) {
ArrowBuf arrowBuf = bufferAllocator.buffer(4 * 1024);
System.out.println(arrowBuf);
}
-Logs without debug allocators enabled:
+Without the debug mode enabled, when we close the allocator, we get this:
.. code-block:: shell
@@ -156,7 +156,7 @@ Logs without debug allocators enabled:
16:28:08.847 [main] ERROR o.apache.arrow.memory.BaseAllocator - Memory was leaked by query. Memory leaked: (4096)
Allocator(ROOT) 0/4096/4096/8192 (res/actual/peak/limit)
-Logs with debug allocators enabled:
+Enabling the debug mode, we get more details:
.. code-block:: shell
@@ -170,7 +170,111 @@ Logs with debug allocators enabled:
ArrowBuf[2], address:140437894463488, length:4096
reservations: 0
+Additionally, in debug mode, `ArrowBuf.print()`_ can be used to obtain a debug string.
+This will include information about allocation operations on the buffer with stack traces, such as when/where the buffer was allocated.
+
+.. code-block:: java
+
+ import org.apache.arrow.memory.ArrowBuf;
+ import org.apache.arrow.memory.BufferAllocator;
+ import org.apache.arrow.memory.RootAllocator;
+
+ try (final BufferAllocator allocator = new RootAllocator()) {
+ try (final ArrowBuf buf = allocator.buffer(1024)) {
+ final StringBuilder sb = new StringBuilder();
+ buf.print(sb, /*indent*/ 0);
+ System.out.println(sb.toString());
+ }
+ }
+
+.. code-block:: text
+
+ ArrowBuf[2], address:140433199984656, length:1024
+ event log for: ArrowBuf[2]
+ 675959093395667 create()
+ at org.apache.arrow.memory.util.HistoricalLog$Event.<init>(HistoricalLog.java:175)
+ at org.apache.arrow.memory.util.HistoricalLog.recordEvent(HistoricalLog.java:83)
+ at org.apache.arrow.memory.ArrowBuf.<init>(ArrowBuf.java:96)
+ at org.apache.arrow.memory.BufferLedger.newArrowBuf(BufferLedger.java:271)
+ at org.apache.arrow.memory.BaseAllocator.bufferWithoutReservation(BaseAllocator.java:300)
+ at org.apache.arrow.memory.BaseAllocator.buffer(BaseAllocator.java:276)
+ at org.apache.arrow.memory.RootAllocator.buffer(RootAllocator.java:29)
+ at org.apache.arrow.memory.BaseAllocator.buffer(BaseAllocator.java:240)
+ at org.apache.arrow.memory.RootAllocator.buffer(RootAllocator.java:29)
+ at REPL.$JShell$14.do_it$($JShell$14.java:10)
+ at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
+ at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
+ at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
+ at java.lang.reflect.Method.invoke(Method.java:566)
+ at jdk.jshell.execution.DirectExecutionControl.invoke(DirectExecutionControl.java:209)
+ at jdk.jshell.execution.RemoteExecutionControl.invoke(RemoteExecutionControl.java:116)
+ at jdk.jshell.execution.DirectExecutionControl.invoke(DirectExecutionControl.java:119)
+ at jdk.jshell.execution.ExecutionControlForwarder.processCommand(ExecutionControlForwarder.java:144)
+ at jdk.jshell.execution.ExecutionControlForwarder.commandLoop(ExecutionControlForwarder.java:262)
+ at jdk.jshell.execution.Util.forwardExecutionControl(Util.java:76)
+ at jdk.jshell.execution.Util.forwardExecutionControlAndIO(Util.java:137)
+ at jdk.jshell.execution.RemoteExecutionControl.main(RemoteExecutionControl.java:70)
+
+Finally, enabling the ``TRACE`` logging level will automatically provide this stack trace when the allocator is closed:
+
+.. code-block:: java
+
+ // Assumes use of Logback; adjust for Log4j, etc. as appropriate
+ import ch.qos.logback.classic.Level;
+ import ch.qos.logback.classic.Logger;
+ import org.apache.arrow.memory.ArrowBuf;
+ import org.apache.arrow.memory.BufferAllocator;
+ import org.apache.arrow.memory.RootAllocator;
+ import org.slf4j.LoggerFactory;
+
+ // Set log level to TRACE to get tracebacks
+ ((Logger) LoggerFactory.getLogger("org.apache.arrow")).setLevel(Level.TRACE);
+ try (final BufferAllocator allocator = new RootAllocator()) {
+ // Leak buffer
+ allocator.buffer(1024);
+ }
+
+.. code-block:: text
+
+ | Exception java.lang.IllegalStateException: Allocator[ROOT] closed with outstanding buffers allocated (1).
+ Allocator(ROOT) 0/1024/1024/9223372036854775807 (res/actual/peak/limit)
+ child allocators: 0
+ ledgers: 1
+ ledger[1] allocator: ROOT), isOwning: , size: , references: 1, life: 712040870231544..0, allocatorManager: [, life: ] holds 1 buffers.
+ ArrowBuf[2], address:139926571810832, length:1024
+ event log for: ArrowBuf[2]
+ 712040888650134 create()
+ at org.apache.arrow.memory.util.StackTrace.<init>(StackTrace.java:34)
+ at org.apache.arrow.memory.util.HistoricalLog$Event.<init>(HistoricalLog.java:175)
+ at org.apache.arrow.memory.util.HistoricalLog.recordEvent(HistoricalLog.java:83)
+ at org.apache.arrow.memory.ArrowBuf.<init>(ArrowBuf.java:96)
+ at org.apache.arrow.memory.BufferLedger.newArrowBuf(BufferLedger.java:271)
+ at org.apache.arrow.memory.BaseAllocator.bufferWithoutReservation(BaseAllocator.java:300)
+ at org.apache.arrow.memory.BaseAllocator.buffer(BaseAllocator.java:276)
+ at org.apache.arrow.memory.RootAllocator.buffer(RootAllocator.java:29)
+ at org.apache.arrow.memory.BaseAllocator.buffer(BaseAllocator.java:240)
+ at org.apache.arrow.memory.RootAllocator.buffer(RootAllocator.java:29)
+ at REPL.$JShell$18.do_it$($JShell$18.java:13)
+ at jdk.internal.reflect.NativeMethodAccessorImpl.invoke0(NativeMethodAccessorImpl.java:-2)
+ at jdk.internal.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
+ at jdk.internal.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
+ at java.lang.reflect.Method.invoke(Method.java:566)
+ at jdk.jshell.execution.DirectExecutionControl.invoke(DirectExecutionControl.java:209)
+ at jdk.jshell.execution.RemoteExecutionControl.invoke(RemoteExecutionControl.java:116)
+ at jdk.jshell.execution.DirectExecutionControl.invoke(DirectExecutionControl.java:119)
+ at jdk.jshell.execution.ExecutionControlForwarder.processCommand(ExecutionControlForwarder.java:144)
+ at jdk.jshell.execution.ExecutionControlForwarder.commandLoop(ExecutionControlForwarder.java:262)
+ at jdk.jshell.execution.Util.forwardExecutionControl(Util.java:76)
+ at jdk.jshell.execution.Util.forwardExecutionControlAndIO(Util.java:137)
+
+ reservations: 0
+
+ | at BaseAllocator.close (BaseAllocator.java:405)
+ | at RootAllocator.close (RootAllocator.java:29)
+ | at (#8:1)
+
.. _`ArrowBuf`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ArrowBuf.html
+.. _`ArrowBuf.print()`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ArrowBuf.html#print-java.lang.StringBuilder-int-org.apache.arrow.memory.BaseAllocator.Verbosity-
.. _`BufferAllocator`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/BufferAllocator.html
.. _`RootAllocator`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/RootAllocator.html
.. _`newChildAllocator`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/RootAllocator.html#newChildAllocator-java.lang.String-org.apache.arrow.memory.AllocationListener-long-long-
@@ -179,4 +283,4 @@ Logs with debug allocators enabled:
.. _`Direct Memory`: https://docs.oracle.com/en/java/javase/11/docs/api/java.base/java/nio/ByteBuffer.html
.. _`ReferenceManager`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ReferenceManager.html
.. _`ReferenceManager.release`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ReferenceManager.html#release--
-.. _`ReferenceManager.retain`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ReferenceManager.html#retain--
\ No newline at end of file
+.. _`ReferenceManager.retain`: https://arrow.apache.org/docs/java/reference/org/apache/arrow/memory/ReferenceManager.html#retain--
diff --git a/java/memory/memory-core/src/main/java/org/apache/arrow/memory/ArrowBuf.java b/java/memory/memory-core/src/main/java/org/apache/arrow/memory/ArrowBuf.java
index 173d0a52dc..7ff11e95d0 100644
--- a/java/memory/memory-core/src/main/java/org/apache/arrow/memory/ArrowBuf.java
+++ b/java/memory/memory-core/src/main/java/org/apache/arrow/memory/ArrowBuf.java
@@ -32,6 +32,7 @@ import org.apache.arrow.memory.util.CommonUtil;
import org.apache.arrow.memory.util.HistoricalLog;
import org.apache.arrow.memory.util.MemoryUtil;
import org.apache.arrow.util.Preconditions;
+import org.apache.arrow.util.VisibleForTesting;
/**
* ArrowBuf serves as a facade over underlying memory by providing
@@ -1097,13 +1098,14 @@ public final class ArrowBuf implements AutoCloseable {
}
/**
- * Prints information of this buffer into <code>sb</code> at the given
+ * Print information of this buffer into <code>sb</code> at the given
* indentation and verbosity level.
*
* <p>It will include history if BaseAllocator.DEBUG is true and
* the verbosity.includeHistoricalLog are true.
*
*/
+ @VisibleForTesting
public void print(StringBuilder sb, int indent, Verbosity verbosity) {
CommonUtil.indent(sb, indent).append(toString());
@@ -1113,6 +1115,16 @@ public final class ArrowBuf implements AutoCloseable {
}
}
+ /**
+ * Print detailed information of this buffer into <code>sb</code>.
+ *
+ * <p>Most information will only be present if BaseAllocator.DEBUG is true.
+ *
+ */
+ public void print(StringBuilder sb, int indent) {
+ print(sb, indent, Verbosity.LOG_WITH_STACKTRACE);
+ }
+
/**
* Get the index at which the next byte will be read from.
* @return reader index
diff --git a/java/memory/memory-core/src/main/java/org/apache/arrow/memory/util/StackTrace.java b/java/memory/memory-core/src/main/java/org/apache/arrow/memory/util/StackTrace.java
index d743af86c2..cd864eb998 100644
--- a/java/memory/memory-core/src/main/java/org/apache/arrow/memory/util/StackTrace.java
+++ b/java/memory/memory-core/src/main/java/org/apache/arrow/memory/util/StackTrace.java
@@ -30,9 +30,9 @@ public class StackTrace {
* Constructor. Captures the current stack trace.
*/
public StackTrace() {
- // skip over the first element so that we don't include this constructor call
final StackTraceElement[] stack = Thread.currentThread().getStackTrace();
- stackTraceElements = Arrays.copyOfRange(stack, 1, stack.length - 1);
+ // Skip first two elements to remove getStackTrace/StackTrace.<init>
+ stackTraceElements = Arrays.copyOfRange(stack, 2, stack.length);
}
/**
diff --git a/java/memory/memory-core/src/test/java/org/apache/arrow/util/TestStackTrace.java b/java/memory/memory-core/src/test/java/org/apache/arrow/util/TestStackTrace.java
new file mode 100644
index 0000000000..4418bec187
--- /dev/null
+++ b/java/memory/memory-core/src/test/java/org/apache/arrow/util/TestStackTrace.java
@@ -0,0 +1,43 @@
+/*
+ * Licensed to the Apache Software Foundation (ASF) under one or more
+ * contributor license agreements. See the NOTICE file distributed with
+ * this work for additional information regarding copyright ownership.
+ * The ASF licenses this file to You under the Apache License, Version 2.0
+ * (the "License"); you may not use this file except in compliance with
+ * the License. You may obtain a copy of the License at
+ *
+ * http://www.apache.org/licenses/LICENSE-2.0
+ *
+ * Unless required by applicable law or agreed to in writing, software
+ * distributed under the License is distributed on an "AS IS" BASIS,
+ * WITHOUT WARRANTIES OR CONDITIONS OF ANY KIND, either express or implied.
+ * See the License for the specific language governing permissions and
+ * limitations under the License.
+ */
+
+package org.apache.arrow.util;
+
+import org.apache.arrow.memory.util.StackTrace;
+import org.junit.jupiter.api.Assertions;
+import org.junit.jupiter.api.Test;
+
+public class TestStackTrace {
+ /**
+ * Check that the stack trace includes the origin line.
+ */
+ @Test
+ public void testStackTraceComplete() {
+ final String stackTrace = new StackTrace().toString();
+ Assertions.assertTrue(stackTrace.contains("TestStackTrace.testStackTraceComplete"), stackTrace);
+ }
+
+ /**
+ * Check that the stack trace doesn't include getStackTrace or StackTrace.
+ */
+ @Test
+ public void testStackTraceOmit() {
+ final String stackTrace = new StackTrace().toString();
+ Assertions.assertFalse(stackTrace.contains("Thread.getStackTrace"), stackTrace);
+ Assertions.assertFalse(stackTrace.contains("org.apache.arrow.memory.util.StackTrace"), stackTrace);
+ }
+}