GH-34723: [Java] Enable log trace for Netty allocator memory usage #35314
Conversation
|
|
|
|
||
| class MemoryLogsAppender extends ListAppender<ILoggingEvent> { | ||
| public boolean contains(List<String> values, Level level) { | ||
| return list.stream() |
There was a problem hiding this comment.
Just inline this? I don't see why we need a subclass and a method
java/memory/memory-netty/src/main/java/io/netty/buffer/PooledByteBufAllocatorL.java
Show resolved
Hide resolved
java/memory/memory-netty/src/test/java/org/apache/arrow/memory/TestBaseAllocator.java
Outdated
Show resolved
Hide resolved
github-actions
bot
added
awaiting changes
github-actions
bot
added
awaiting change review
| boolean result = listAppenderContains.apply(Arrays.asList("Memory Usage: \n", "Large buffers outstanding: ", | ||
| "Normal buffers outstanding: "), | ||
| Level.TRACE); | ||
| logger.detachAppender(memoryLogsAppender); |
There was a problem hiding this comment.
this needs to be in a try-finally
| BiFunction<List<String>, Level, Boolean> listAppenderContains = | ||
| (List<String> values, Level level) -> memoryLogsAppender.list.stream() | ||
| .anyMatch( | ||
| log -> log.toString().contains(values.get(0)) && | ||
| log.toString().contains(values.get(1)) && | ||
| log.toString().contains(values.get(2)) && | ||
| log.getLevel().equals(level) | ||
| ); | ||
| boolean result = listAppenderContains.apply(Arrays.asList("Memory Usage: \n", "Large buffers outstanding: ", | ||
| "Normal buffers outstanding: "), | ||
| Level.TRACE); |
| public void testMemoryUsage() { | ||
| ListAppender<ILoggingEvent> memoryLogsAppender = new ListAppender<>(); | ||
| Logger logger = (Logger) LoggerFactory.getLogger("arrow.allocator"); | ||
| logger.setLevel(Level.TRACE); |
There was a problem hiding this comment.
Reset the log level afterwards, too
| memoryLogsAppender.start(); | ||
| try (ArrowBuf buf = new ArrowBuf(ReferenceManager.NO_OP, null, | ||
| 1024, new PooledByteBufAllocatorL().empty.memoryAddress())) { | ||
| buf.memoryAddress(); |
There was a problem hiding this comment.
What I'm saying is, you have no guarantee the logger will actually have logged anything by the time the next few lines run. So this is just adding a flaky test.
There was a problem hiding this comment.
And IMO, the easier way to test this would be to factor out a function that generates the log string, test that function, and use that function from the thread, rather than hooking into the physical logger.
There was a problem hiding this comment.
Validation inside a loop
github-actions
bot
added
awaiting changes
github-actions
bot
added
awaiting change review
| boolean result = false; | ||
| long startTime = System.currentTimeMillis(); | ||
| while (true && (System.currentTimeMillis() - startTime) < 20000) { | ||
| result = listAppenderContains.apply(Arrays.asList("Memory Usage: \n", "Large buffers outstanding: ", |
There was a problem hiding this comment.
Again...why the lambda? Just write it out as a loop
| ); | ||
| boolean result = false; | ||
| long startTime = System.currentTimeMillis(); | ||
| while (true && (System.currentTimeMillis() - startTime) < 20000) { |
There was a problem hiding this comment.
Moved inside de loop to try to read logs for 10 seconds maximum, then finished with error.
| assertTrue(result); | ||
| } finally { | ||
| logger.detachAppender(memoryLogsAppender); | ||
| logger.setLevel(null); |
There was a problem hiding this comment.
Shouldn't we reset it to what it originally was?
There was a problem hiding this comment.
Initially it was marked with null
| try (ArrowBuf buf = new ArrowBuf(ReferenceManager.NO_OP, null, | ||
| 1024, new PooledByteBufAllocatorL().empty.memoryAddress())) { | ||
| buf.memoryAddress(); |
There was a problem hiding this comment.
Why can't we just use an allocator to create the buffer?
There was a problem hiding this comment.
Just trying to use allocator but for some reason the log is not populated if I run the test by command line, but able to populate log if I run the same test with allocator thru the IDE.
github-actions
bot
added
awaiting changes
github-actions
bot
added
awaiting change review
| log.toString().contains("Normal buffers outstanding: ") && | ||
| log.getLevel().equals(Level.TRACE) | ||
| ); | ||
| if (result || (System.currentTimeMillis() - startTime) > 10000) { // 10 seconds maximum for time to write logs |
There was a problem hiding this comment.
you could just make this the loop guard?
github-actions
bot
added
awaiting changes
github-actions
bot
added
awaiting change review
github-actions
bot
added
awaiting merge
|
Conbench analyzed the 7 benchmark runs on commit There were no benchmark performance regressions. 🎉 The full Conbench report has more details. |
Rationale for this change
To close #34723
What changes are included in this PR?
Enable log trace for Netty allocator memory usage
Are these changes tested?
New log enabled:
Logs:
Are there any user-facing changes?
No