偶然读到LMAX Disruptor

因为一个偶然的机会读到LMAX Disruptor，这个项目里最核心的那个Ring Buffer真是一个巧妙的解决方案。 当年在英特尔的时候也需要解决类似的问题，可惜还没有到需要解决这么极致的性能问题的时候项目就夭折了。

sun.nio.ch.Util managed direct buffer and thread reusing

Background

As I mentioned in previous blog, there is a memory fragmentation problem within our application, and tunning the JVM parameters can resolve the problem, but it doesn't answer the question who is creating so many direct buffers and use them for short time? Because it's against the recommendation of ByteBuffer.allocateDirect():

It is therefore recommended that direct buffers be allocated primarily for large, long-lived buffers that are subject to the underlying system's native I/O operations.

Analysis

To answer this question, I created a simple program to monitor the caller of ByteBuffer.allocateDirect(int) through JDI, and got following output (some stack are omitted):

java.nio.ByteBuffer.allocateDirect(int): count=124, size=13463718
  sun.nio.ch.Util.getTemporaryDirectBuffer(int): count=124, size=13463718
    sun.nio.ch.IOUtil.write(java.io.FileDescriptor, java.nio.ByteBuffer, long, sun.nio.ch.NativeDispatcher): count=1, size=447850
      sun.nio.ch.SocketChannelImpl.write(java.nio.ByteBuffer): count=1, size=447850
        org.eclipse.jetty.io.ChannelEndPoint.flush(java.nio.ByteBuffer[]): count=1, size=447850
    sun.nio.ch.IOUtil.write(java.io.FileDescriptor, java.nio.ByteBuffer[], int, int, sun.nio.ch.NativeDispatcher): count=102, size=12819260
      sun.nio.ch.SocketChannelImpl.write(java.nio.ByteBuffer[], int, int): count=102, size=12819260
        org.eclipse.jetty.io.ChannelEndPoint.flush(java.nio.ByteBuffer[]): count=102, size=12819260
    sun.nio.ch.IOUtil.read(java.io.FileDescriptor, java.nio.ByteBuffer, long, sun.nio.ch.NativeDispatcher): count=21, size=196608
      sun.nio.ch.SocketChannelImpl.read(java.nio.ByteBuffer): count=21, size=196608
        org.eclipse.jetty.io.ChannelEndPoint.fill(java.nio.ByteBuffer): count=21, size=196608

The count is the number of direct buffers, and the size is the total size of buffers. According the monitoring result, those direct buffers are all allocated by JDK default implementation of SocketChannel, when the user pass a non-direct buffer to perform I/O. After read the source code of sun.nio.ch.Util, I found it uses a thread local cache to keep the direct buffer. While the sun.nio.ch.Util is designed carefully to limit the total number of cached buffers (8 per thread), and clean direct buffer while it's removed from the cache. The only possible reason is there are too many new threads, and the buffers in cache are not used at all.

Root Cause

Our application uses Jetty to handle HTTP requests, and there is a custom class wraps Jetty Server, in this wrapper class, a ThreadPoolExecutor is used like following:

ExecutorService executor = new ThreadPoolExecutor(
 minThreads,
 maxThreads,
 maxIdleTimeMs,
 TimeUnit.MILLISECONDS,
 new SynchronousQueue());
Server server = new Server(new ExecutorThreadPool(executor));

Unfortunately, the minThreads is 2 and maxIdleTimeMs is 5000ms, and the Jetty Server will use 12 threads from the pool for accepting and selector. Which means the total number of threads is always bigger than the minThreads. When the service is not very busy, a worker thread will be discarded, and a new worker thread will be created when a new request comes. In this situation, the cached buffers in sun.nio.ch.Util will no longer be used and will only been collected when GC triggered.

Understanding about CMSInitiatingOccupancyFraction and UseCMSInitiatingOccupancyOnly

While reading the Useful JVM Flags – Part 7 (CMS Collector), I was impressed that CMSInitiatingOccupancyFraction was useless when UseCMSInitiatingOccupancyOnly is false (default) except the first CMS collection:

We can use the flag -XX+UseCMSInitiatingOccupancyOnly to instruct the JVM not to base its decision when to start a CMS cycle on run time statistics. Instead, when this flag is enabled, the JVM uses the value of CMSInitiatingOccupancyFraction for every CMS cycle, not just for the first one.

After checking the source code, I found this statement is inaccurate, a more accurate statement would be:
When UseCMSInitiatingOccupancyOnly is false (default), a CMS collection may be triggered even the actual occupancy is smaller than the specified CMSInitiatingOccupancyFraction value. In other words, when actual occupancy is greater than the specified CMSInitiatingOccupancyFraction value, a CMS collection will be triggered.

Detail Explanation

Code snippet from OpenJDK (openjdk/hotspot/src/share/vm/gc_implementation/concurrentMarkSweep/concurrentMarkSweepGeneration.cpp):

  // If the estimated time to complete a cms collection (cms_duration())
  // is less than the estimated time remaining until the cms generation
  // is full, start a collection.
  if (!UseCMSInitiatingOccupancyOnly) {
    if (stats().valid()) {
      if (stats().time_until_cms_start() == 0.0) {
        return true;
      }
    } else {
      // We want to conservatively collect somewhat early in order
      // to try and "bootstrap" our CMS/promotion statistics;
      // this branch will not fire after the first successful CMS
      // collection because the stats should then be valid.
      if (_cmsGen->occupancy() >= _bootstrap_occupancy) {
        if (Verbose && PrintGCDetails) {
          gclog_or_tty->print_cr(
            " CMSCollector: collect for bootstrapping statistics:"
            " occupancy = %f, boot occupancy = %f", _cmsGen->occupancy(),
            _bootstrap_occupancy);
        }
        return true;
      }
    }
  }

  // Otherwise, we start a collection cycle if either the perm gen or
  // old gen want a collection cycle started. Each may use
  // an appropriate criterion for making this decision.
  // XXX We need to make sure that the gen expansion
  // criterion dovetails well with this. XXX NEED TO FIX THIS
  if (_cmsGen->should_concurrent_collect()) {
    if (Verbose && PrintGCDetails) {
      gclog_or_tty->print_cr("CMS old gen initiated");
    }
    return true;
  }

In above code, the _cmsGen->should_concurrent_collect() is always been called, unless it's already determined that a collection is needed. In the implementation of _cmsGen->should_concurrent_collect(), the CMSInitiatingOccupancyFraction value is checked at beginning.

bool ConcurrentMarkSweepGeneration::should_concurrent_collect() const {

  assert_lock_strong(freelistLock());
  if (occupancy() > initiating_occupancy()) {
    if (PrintGCDetails && Verbose) {
      gclog_or_tty->print(" %s: collect because of occupancy %f / %f  ",
        short_name(), occupancy(), initiating_occupancy());
    }
    return true;
  }
  if (UseCMSInitiatingOccupancyOnly) {
    return false;
  }
  if (expansion_cause() == CMSExpansionCause::_satisfy_allocation) {
    if (PrintGCDetails && Verbose) {
      gclog_or_tty->print(" %s: collect because expanded for allocation ",
        short_name());
    }
    return true;
  }
  if (_cmsSpace->should_concurrent_collect()) {
    if (PrintGCDetails && Verbose) {
      gclog_or_tty->print(" %s: collect because cmsSpace says so ",
        short_name());
    }
    return true;
  }
  return false;
}

From the above code, it's easy to find out that CMSBootstrapOccupancy is been used for first collection if UseCMSInitiatingOccupancyOnly is false.

Summary

The UseCMSInitiatingOccupancyOnly need to be set to true only if you want to avoid the early collection before occupancy reaches the specified value. Looks it's not the case when CMSInitiatingOccupancyFraction is set to a small value. For example you application allocated direct buffers frequently and you may want to collect garbage even the old generation utilization is quite low.

Java RSS increased by memory fragmentation

Recently, I found a strange memory related problem with our product system, that the RSS (resident set size) increased over time. The Java heap utilization is less than 50%, looks like there could be a native memory leak, while it turns out something else.

Leaking Direct Buffer?

Direct Buffer is one of the potential native memory leak causes, so first  checked the Direct Buffer with the tool from Alan Bateman's blog. It shows the direct buffers as following:

          direct                        mapped
 Count   Capacity     Memory   Count   Capacity     Memory
   419  123242031  123242031       0          0          0
   419  123242031  123242031       0          0          0
   421  123299674  123299674       0          0          0

There is no strong evidence about that it's caused by direct buffer.

Per-thread malloc?

While checking the memory usage of the java process with pmap, I found some strange 64MB memory blocks, similar as described in Lex Chou's blog (Chinese). So that I tried to set the MALLOC_ARENA_MAX environment variable. Unfortunately, the problem is still not resolved.

Native Heap Fragmentation?

With further investigation, I found this problem could be caused by memory fragmentation, as described in this bug report.The malloc() implementation works fine for general applications, while it's not able/necessary to support all kinds of applications.
By using gdb, I found the real evidence:

gdb --pid <pid>
(gdb) call malloc_stats()

And got following output:

Arena 0:
system bytes     = 2338504704
in use bytes     =   69503376
Arena 1:
system bytes     =   48705536
in use bytes     =   19162544
Arena 2:
system bytes     =     806912
in use bytes     =     341776
Arena 3:
system bytes     =   17965056
in use bytes     =   17505488
Total (incl. mmap):
system bytes     = 2444173312
in use bytes     =  144704288
max mmap regions =         59
max mmap bytes   =  154546176

So there are about 2.4GB memory been allocated from system, but only used about 144MB. This is a strong indicator of problem, so that I set MALLOC_MMAP_THRESHOLD_ to 131072, and monitor the result. Seems the RSS could draw down after long running, but it still raised too high (9G).

Conclusion

After monitoring the application for long time, the actual problem is  complicated and caused by multiple problems. First, the heap fragmentation is the major contributor of this problem, second, this application creates lots of transient objects, and some direct byte buffers are kept for little longer time. Which means those byte buffers are moved to old generation because of frequent young GC. After that there is very few GC in old generation since it's not full. So that those byte buffers are not garbage collected.
To resolve this problem, a small CMSInitiatingOccupancyFraction is used together with UseCMSInitiatingOccupancyOnly option. then the total RSS looks quite stable now.

万年历

年末休假中，总想找点什么事情做做，lp说要买个挂历，我说我给你做吧，因为很早以前就见过别人写过很不错的万年历，觉着挺有意思的，曾经试图仿着写一个Java版本的农历，不过一直都没有做起来。

既然有几天假期，于是又开始蠢蠢欲动了，于是上网去找相关的资料，看看有没有现成的咚咚，我可不想重新发明轮子。

网上有很多的万年历，但是真正作者却很少，因为很多人都是抄来抄去。之前我看过一个叫做知来者的万年历，写得很好，精确度很高，还是难得的开放源代码的程序，但是作者却神龙不见首尾，连个联系方式都失效了。这次又找到了他的一个blog，虽然也有一年多没更新了，不过还是知道了两点，一是他还是移动万年历MobCal的真正作者，二是他的email地址，虽然我没有和他打过交道，但是就目前国内的IT圈子里，一个认真做事的开放源代码程序员是值得敬佩的。

另外就是很顺利地在一个农历论坛找到了一个很不错JavaScript版本的叫做寿星万年历，作者许剑伟，似乎是福建莆田十中的一个中学教师。这个程序算法是基于天文算法做出来的历法，准确性很高，还能计算日月食等等天文相关的数据。
仔细读了一下这位许老师的一些帖子发现，他是一个非常能钻研的人，做这个程序之前，他并没有很多天文历法方面的知识，然而通过一段时间的努力，他阅读了大量的天文资料，做出了实实在在的成果，并且翻译了《天文算法》这本书，这一切，都是在一年之内完成的。

回想一下自己在这一年，没有什么长进，一直都以很忙做为借口，想做的事却一直没有动手去做，实在是惭愧。“做到”这两个字，是当前的我最需要注意的。

关于字节流的一个争论（二）

上次简单说了一下问题，这次就说说争论的过程，也算是一个影响失败的教训。

话说英国人收到了我开的bug之后，第二天就给我回信了，我还正高兴呢！心想这老外的效率真高，可打开邮件我就傻眼了，人家效率是高，可惜这个效率是把皮球踢回来的效率，不是解决问题的效率。
在邮件里，英国人首先指出我提供的例子不符合Java序列化的要求，让我去读一下Java序列化的规范，因为我在writeObject()里面少调了defaultWriteObject或writeFields()，blabla了一大堆，朋友们哪，这就是踢皮球的第一计，叫做围魏救赵。不过这个还是容易对付的，于是直接了当地和他们说，我给你的只是一段例子，为了展示问题而已，写不写这个不影响问题的展现，请解释问题吧。

很快，英国人的第二封邮件过来了，还是让我看Java序列化的规范，这次的理由是按照Java序列化的规范，读写必须一致，也就是说任何一次写数据，都必须要有同类型的一次读操作。我已开始觉得这个说法挺合理的，也仔细想就犯了一个错误，没有在第一时间反驳其说法的不严谨，导致了后面的长期扯皮。
在此之后，又有几个来回，最终对方直接就忽略掉我的邮件，这个事情就这样不了了之了。

关于字节流的一个争论（一）

最近一段时间，和一个英国人争论了很久，其实来回也没几封邮件，但是对方每次回都要隔一两天，所以就拖了很久，而且最终也没有解决，看来我的影响力（Influence）还是很需要提高的。

问题其实很简单，我们的代码里需要序列化一个数据对象，序列化前它是很多个字节数组(byte array)，这个是因为这个对象类似ByteArrayOutputStream，它是慢慢变大的，一开始的时候我们并不知道它有多大，如果用单个数组，在变大的过程中需要不断申请新的大块内存，可能会导致内存不够的错误。因为我们关心的是数据，反序列化之后则只需要恢复成一个数组就好了。

所以我们的主要逻辑就类似于下面这样的伪代码：

class ValueObject {
   private transient List<byte[]> values;
   private transient byte[] data;
   private void writeObject(ObjectOutputStream output) {
       output.writeInt(totalLength); // write out the total length of bytes
       for (byte[] value : values) {
           output.write(value, 0, value.length);
       }
   }

   private void readObject(ObjectInputStream input) {
       int length = input.readInt();
       data = new byte[length];
       input.read(data, 0, length);
   }
}

换句话说，我们的主要想法就是写的时候分开写，读的时候一次读，这个逻辑本来是没有问题的，因为Java里面的流(stream)指的就是字节流，比如OutputStream里面明确申明：
This abstract class is the superclass of all classes representing an output stream of bytes.
既然是流，我怎么往里面写数据，另外一头怎么读应该任意，只要我读写的总字节数对上了就OK，而且大部分I/O类也都是这么实现的，所以这段代码一直都能很好地工作，似乎从来没有问题。

然而，我们还是碰到了一个问题，当我们的对象通过RMI-IIOP传输的时候，竟然导致了一个错误。经过测试，发现了一个奇怪的现象，那就是IIOP的I/O流和普通的流的行为是不一致的，具体就是当数组比较大的时候，当你写出一个字节数组，那么对应地必须读一个字节数组，写两次就得读两次，而且这个问题只在字节数组比较大的时候才会出现问题，小数组是没有问题的。

为什么会有这么奇怪的问题呢？仔细读过这方面的实现代码CDRInputStream后发现，IIOP是把数据分区块(block)传输的，比如这一头做了很多次写，如果数据不多的话（小于等于区块大小），但是传输是一个区块过去的，而对于字节数组，如果大于区块大小，就会是一个单独的区块。问题在于，区块是有边界标志的，读的时候，应该检查边界标志，事实上CDRInputStream也是这么做了，然而不幸的是，当用户读一个字节数组的时候，它假定用户指定的长度刚好就是区块的大小，并不判断是否超出当前区块，问题就出现了。

IT民工看到这儿，基本上立刻意识到，这不就是一个简单的错误么？检查一下边界就好了。于是我立刻给我们公司负责JDK ORB的组开了一个bug，要求他们解决这个问题，我以为他们应该很容易改掉，可是没有想到，这个问题竟然也成了一个扯皮的问题，最后竟然没法解决了！

具体过程有点复杂，下次再写。