Uploaded image for project: 'Thrift'
  1. Thrift
  2. THRIFT-5494

byte count of FrameBuffer(AbstractNonblockingServer.readBufferBytesAllocated) is not subtracted

    XMLWordPrintableJSON

Details

    • Bug
    • Status: Resolved
    • Major
    • Resolution: Fixed
    • 0.9.1
    • 0.17.0
    • Java - Library
    • None

    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? 

      Attachments

        1. image-2022-02-24-11-49-57-579.png
          337 kB
          wangfan
        2. image-2022-02-24-11-45-24-002.png
          48 kB
          wangfan
        3. image-2022-02-24-11-40-14-321.png
          45 kB
          wangfan
        4. image-2022-02-24-11-31-50-880.png
          45 kB
          wangfan

        Issue Links

          Activity

            People

              wangfan wangfan
              Evil shanzhongkai
              Votes:
              0 Vote for this issue
              Watchers:
              3 Start watching this issue

              Dates

                Created:
                Updated:
                Resolved:

                Time Tracking

                  Estimated:
                  Original Estimate - Not Specified
                  Not Specified
                  Remaining:
                  Remaining Estimate - 0h
                  0h
                  Logged:
                  Time Spent - 5h
                  5h