Uploaded image for project: 'Cassandra'
  1. Cassandra
  2. CASSANDRA-14855

Message Flusher scheduling fell off the event loop, resulting in out of memory

    XMLWordPrintableJSON

    Details

    • Severity:
      Normal

      Description

      We recently had a production issue where about 10 nodes in a 96 node cluster ran out of heap.

      From heap dump analysis, I believe there is enough evidence to indicate `queued` data member of the Flusher got too big, resulting in out of memory.
      Below are specifics on what we found from the heap dump (relevant screenshots attached):

      • non-empty "queued" data member of Flusher having retaining heap of 0.5GB, and multiple such instances.
      • "running" data member of Flusher having "true" value
      • Size of scheduledTasks on the eventloop was 0.

      We suspect something (maybe an exception) caused the Flusher running state to continue to be true, but was not able to schedule itself with the event loop.
      Could not find any ERROR in the system.log, except for following INFO logs around the incident time.

      INFO [epollEventLoopGroup-2-4] 2018-xx-xx xx:xx:xx,592 Message.java:619 - Unexpected exception during request; channel = [id: 0x8d288811, L:/xxx.xx.xxx.xxx:7104 - R:/xxx.xx.x.xx:18886]
      io.netty.channel.unix.Errors$NativeIoException: readAddress() failed: Connection timed out
       at io.netty.channel.unix.Errors.newIOException(Errors.java:117) ~[netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.unix.Errors.ioResult(Errors.java:138) ~[netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.unix.FileDescriptor.readAddress(FileDescriptor.java:175) ~[netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.epoll.AbstractEpollChannel.doReadBytes(AbstractEpollChannel.java:238) ~[netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.epoll.AbstractEpollStreamChannel$EpollStreamUnsafe.epollInReady(AbstractEpollStreamChannel.java:926) ~[netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.epoll.EpollEventLoop.processReady(EpollEventLoop.java:397) [netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.channel.epoll.EpollEventLoop.run(EpollEventLoop.java:302) [netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.util.concurrent.SingleThreadEventExecutor$2.run(SingleThreadEventExecutor.java:131) [netty-all-4.0.44.Final.jar:4.0.44.Final]
       at io.netty.util.concurrent.DefaultThreadFactory$DefaultRunnableDecorator.run(DefaultThreadFactory.java:144) [netty-all-4.0.44.Final.jar:4.0.44.Final]
      

      I would like to pursue the following proposals to fix this issue:

      1. ImmediateFlusher: Backport trunk's ImmediateFlusher ( CASSANDRA-13651 https://github.com/apache/cassandra/commit/96ef514917e5a4829dbe864104dbc08a7d0e0cec) to 3.0.x and maybe to other versions as well, since ImmediateFlusher seems to be more robust than the existing Flusher as it does not depend on any running state/scheduling.
      2. Make "queued" data member of the Flusher bounded to avoid any potential of causing out of memory due to otherwise unbounded nature.

        Attachments

        1. blocked_thread_pool.png
          330 kB
          Sumanth Pasupuleti
        2. cpu.png
          1.06 MB
          Sumanth Pasupuleti
        3. eventloop_scheduledtasks.png
          239 kB
          Sumanth Pasupuleti
        4. flusher running state.png
          208 kB
          Sumanth Pasupuleti
        5. heap_dump.png
          1.10 MB
          Sumanth Pasupuleti
        6. heap.png
          1.23 MB
          Sumanth Pasupuleti
        7. read_latency.png
          536 kB
          Sumanth Pasupuleti

          Issue Links

            Activity

              People

              • Assignee:
                sumanth.pasupuleti Sumanth Pasupuleti
                Reporter:
                sumanth.pasupuleti Sumanth Pasupuleti
                Authors:
                Sumanth Pasupuleti
                Reviewers:
                Benedict Elliott Smith
              • Votes:
                0 Vote for this issue
                Watchers:
                7 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 - 20m
                  20m