[THRIFT-5494] byte count of FrameBuffer(AbstractNonblockingServer.readBufferBytesAllocated) is not subtracted

• Type: Bug
• Status: Closed
• Priority: Major
• Resolution: Fixed
• Affects Version/s: 0.9.1
• Fix Version/s: 0.17.0
• Component/s: Java - Library

Language

Java

• Assignee: wangfan
• Reporter: shanzhongkai
• Created: 04/Jan/22 03:54
• Updated: 26/Oct/22 23:46
• Resolved: 06/Mar/22 11:36

Description

AbstractNonblockingServer.readbufferbytesallocated is used to indicate “How many bytes are currently allocated to read buffers.”, however, we find that readbufferbytesallocated does not decrease as expected in rare cases. we added the following logs in FrameBuffer.read:

// if this frame will push us over the memory limit, then return.
// with luck, more memory will free up the next time around.
LOGGER.info("print readBufferBytesAllocated: {}, {}",  readBufferBytesAllocated.get(), frameSize);
if (readBufferBytesAllocated.get() + frameSize > MAX_READ_BUFFER_BYTES) {
  return true;
} 

and we found:

2022-01-04,11:30:06,795 {Thread-104} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 135
2022-01-04,11:30:06,795 {Thread-106} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 144
2022-01-04,11:30:06,795 {Thread-107} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 51315
2022-01-04,11:30:06,795 {Thread-118} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 135
2022-01-04,11:30:06,795 {Thread-121} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 170
2022-01-04,11:30:06,795 {Thread-124} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 360495
2022-01-04,11:30:06,795 {Thread-107} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141441140, 140
2022-01-04,11:30:06,807 {Thread-114} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 257970
2022-01-04,11:30:06,823 {Thread-112} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 139
2022-01-04,11:30:06,839 {Thread-110} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 30308
2022-01-04,11:30:06,843 {Thread-110} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 34608
2022-01-04,11:30:06,868 {Thread-120} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 162
2022-01-04,11:30:06,872 {Thread-107} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 144
2022-01-04,11:30:06,879 {Thread-125} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 279360
2022-01-04,11:30:06,918 {Thread-106} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 118
2022-01-04,11:30:06,924 {Thread-104} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 158
2022-01-04,11:30:06,971 {Thread-115} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 36964
2022-01-04,11:30:06,974 {Thread-115} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 129
2022-01-04,11:30:07,033 {Thread-121} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 170
2022-01-04,11:30:07,036 {Thread-112} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 26714
2022-01-04,11:30:07,038 {Thread-121} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 132
2022-01-04,11:30:07,074 {Thread-107} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 33878
2022-01-04,11:30:07,079 {Thread-120} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 162
2022-01-04,11:30:07,113 {Thread-122} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 132
2022-01-04,11:30:07,149 {Thread-108} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 26607
2022-01-04,11:30:07,192 {Thread-110} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 31055
2022-01-04,11:30:07,244 {Thread-114} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 166
2022-01-04,11:30:07,260 {Thread-121} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 170
2022-01-04,11:30:07,288 {Thread-106} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 108
2022-01-04,11:30:07,417 {Thread-124} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 132
2022-01-04,11:30:07,441 {Thread-110} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 135
2022-01-04,11:30:07,469 {Thread-115} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 35387
2022-01-04,11:30:07,571 {Thread-121} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 170
2022-01-04,11:30:07,571 {Thread-122} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 131
2022-01-04,11:30:07,571 {Thread-105} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 132
2022-01-04,11:30:07,571 {Thread-102} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 143
2022-01-04,11:30:07,571 {Thread-117} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 125
2022-01-04,11:30:07,615 {Thread-114} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 885819
2022-01-04,11:30:07,623 {Thread-116} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141914545, 36155
2022-01-04,11:30:07,624 {Thread-112} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141914545, 16293
2022-01-04,11:30:07,636 {Thread-107} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 1119
2022-01-04,11:30:07,683 {Thread-106} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 131
2022-01-04,11:30:07,686 {Thread-123} [INFO] libthrift091.server.AbstractNonblockingServer$AsyncFrameBuffer: print readBufferBytesAllocated: 141028722, 7875

It seems that readbufferbytesallocated has not decreased as expected. The ultimate performance of this problem is that the CPU is getting higher and higher, because the cache is less and less, the incoming large requests cannot allocate the cache, resulting in the large requests falling into an endless loop.

 

https://issues.apache.org/jira/projects/THRIFT/issues/THRIFT-5468?filter=allopenissues

The problem in this link is different from ours, because this problem has been fixed in 0.9.1. What may be the reason why the readbufferbytesallocated  has not decreased? 

Issue Links

• links to: GitHub Pull Request #2533