Building Distributed Cache with GlusterFS - not a good idea

Cache is a popular concept. You can't survive in the cruel word of programming without using cache. Cache is inside you cpu. There is one inside you browser. Your favorite web site is serving pages from cache and you probably have one in your brain as well :)

Anyway, my mission was to build a distributed cache which can be used to speedup application X. This cache needed to be scalable and to allow extending it by adding more compute nodes. The compute nodes should be cheap amazon instances and the cache should provide very low latency (time until first byte of data arrives should be around 5ms).

Distributed file systems are a very cool peace of technology, so naturally it seems as a good idea to use it in building this cache. After reading about Ceph vs Gluster wars I've decided to settle down on Gluster. I liked very much the idea of translators which add functionality layer by layer. Each translator is a simple unit which handles one task of complicated file system.

The DHT translator in Gluster allows to distribute files between the different nodes. Later when the client wants to read file, it can locate the correct node using O(1) hash function computation and to read it directly from the node where it is located.

Using amazon, I quickly created 5 m1.large instances and installed glusterfs. The installation is pretty easy. I used my favorite tool for repeating tasks on multiple compute nodes (fabric) and after a while installation of x nodes became as simple as running

>> fab -H hostname1,hostname2,hostnamexx -P -f gluster.py install_gluster create_volume create_mount

Next I created distributed glusterfs volume consisting of 5 nodes

>> gluster volume create cache hostname1:/brick1/cache hostname2:/brick1/cache hostname3:/brick1/cache hostname4:/brick1/cache hostname5:/brick1/cache

I modified application X code to try and use the remote cache and my algorithm became something similar to:

fd = open("/local_cache/file1/block1.bin", O_RDONLY);
if (fd == -1) {
    fd = open("/gluster/file1/block1.bin", O_RDONLY);   
...
pread(fd, ....)

And it worked well when there was small amount of application X instances (around 10). However when the amount of application X instances was increased (8 servers, 15 application X instances on each, total of 120 applications which continuously access glusterfs through fuse interface), I've noticed that access to mounted glusterfs file system became very slow.

Looking at latency of some of the glusterfs operation on client side (thanks good gluster has translator, called debug/io-stats, which can aggregate statistics), I've noticed that some of the lookup operation would take 10-20 seconds ! Basically lookup should be very lite operation, using the DHT translator the client should determine the exact server where the file should be located and then it can query it directly which will lead to distribution of stress between the 5 nodes. Each time I open the file a lookup command will be sent by gluster to determine where the file is located and later I can read it or write to it without a problem.

Fop     Call Count    Avg-Latency  Min-Latency    Max-Latency
---     ----------    -----------  -----------    -----------
STAT            58     2133.43 us      1.00 us    62789.00 us
MKDIR          112  1009804.77 us     18.00 us 14452294.00 us
OPEN           149    22108.78 us      2.00 us  1778858.00 us
READ           151   160008.16 us      7.00 us  7246801.00 us
FLUSH          149    13178.94 us      1.00 us  1594615.00 us
SETXATTR      2633   232459.26 us    719.00 us 10749344.00 us
LOOKUP        4725   641604.43 us      2.00 us 17630043.00 us
FORGET           1           0 us         0 us           0 us
RELEASE        149           0 us         0 us           0 us
------ ----- ----- ----- ----- ----- --- -----  ----- ----- ---

So why are lookups take so much time ? I realized I need to look at the network level. Luckily glusterfs has plugin for wireshark which can dissect traffic and show glusterfs operations.

Looking at the captured packets I saw that when we access file /file1/block1.bin, gluster will invoke 3 lookup operations. First for directory /, second for sub-directory file1 and then to file block1.bin.

Now here are the bad news: when performing lookup for directory, gluster will broadcast lookup request to all nodes and then wait until all nodes will respond. In my case one of the nodes (not the one where the actual file sits) would be super busy and would respond only after 5 seconds. And so the lookup request will wait for 5 seconds without trying to continue and actually communicate with the node where the file is located. This bad situation repeats for each path directory component and leads to awful performance with lookups.

Tweaking glusterfs options such as setting dht.lookup-unhashed=off, didn't help since this only relevant the file component and we still need to traverse at least two directory components until we reach the file component in the path.

So in my opinion such behavior makes gluster very unsuitable for functioning as cache where checking if data is in cache (lookup) is a frequent method. I guess hacking gluster and modifying the DHT translator can solve the issue (and introduce many other interesting issues :)

But this would be another interesting post ...

Using performance counters on linux

One extremely useful feature linux has to offer is the ability to profile your system (user space and kernel) using the perf utility.

In a nutshell this utility allows you to count hardware and software events in linux kernel. Additional bonus is that when you count these events you can record cpu instruction pointer at the time of the event. Instruction pointer records, later can be used to generate concise execution profile of the kernel/user space code.

Similarly to git, perf uses sub-utils to introduce various functionality:

The first step is to list available events:

root@dev-12:# perf list

List of pre-defined events (to be used in -e):
  cpu-cycles OR cycles                               [Hardware event]
  stalled-cycles-frontend OR idle-cycles-frontend    [Hardware event]
  stalled-cycles-backend OR idle-cycles-backend      [Hardware event]
  instructions                                       [Hardware event]
  cache-references                                   [Hardware event]
  cache-misses                                       [Hardware event]
  branch-instructions OR branches                    [Hardware event]
  branch-misses                                      [Hardware event]
  bus-cycles                                         [Hardware event]

  cpu-clock                                          [Software event]
  task-clock                                         [Software event]
  page-faults OR faults                              [Software event]

There are tons of events which we can divide into the following main categories:

• Hardware events
• Hardware cache events
• Software events
• Tracepoint events

Tracepoints events are special places in kernel that were specified by developers as a good position to trace. Stopping there usually brings you to the location where some important kernel functions starts or completes.

For example block:block_rq_complete  trace event is passed when block i/o request completes.

Hardware events make use of special cpu hardware registers, which count cpu cpecific hardware events and trigger interrupt when certain threshold is passed. Software events do not require special hardware support and usually generated by kernel handlers which process special events such as page fault.

To watch statistics of events in the system you can use stat command:

root@dev-12:# perf stat -e syscalls:sys_enter_write,page-faults \

                                       echo hello world > 1.txt

 Performance counter stats for 'echo hello world':

                 1 syscalls:sys_enter_write                                    
               165 page-faults                                                 

       0.001013974 seconds time elapsed

filtering using -e flag is possible and it is possible to count events on existing process using -p flag

Another step in using perf is to realize that events can be recorded using record command:

root@dev-12:# perf record -f hdparm -t /dev/vda > /dev/null
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.038 MB perf.data (~1673 samples) ]

And later code execution profile can be created using report command (each time event occur the current instruction pointer is recorded as well):

root@dev-12:/home/local/a/hdparm-9.37# perf report
# Events: 1K cpu-clock
#
# Overhead  Command      Shared Object                                Symbol
# ........  .......  .................  ....................................
#
    25.80%   hdparm  [kernel.kallsyms]  [k] copy_user_generic_string
     8.21%   hdparm  [kernel.kallsyms]  [k] blk_flush_plug_list
     4.69%   hdparm  [kernel.kallsyms]  [k] get_page_from_freelist
     3.62%   hdparm  [kernel.kallsyms]  [k] add_to_page_cache_locked
     3.09%   hdparm  hdparm             [.] read_big_block
     2.77%   hdparm  [kernel.kallsyms]  [k] _raw_spin_unlock_irqrestore
     2.51%   hdparm  [kernel.kallsyms]  [k] kmem_cache_alloc
     1.87%   hdparm  [kernel.kallsyms]  [k] __mem_cgroup_commit_charge
     1.76%   hdparm  [kernel.kallsyms]  [k] file_read_actor
     1.76%   hdparm  [kernel.kallsyms]  [k] __alloc_pages_nodemask
     1.55%   hdparm  [kernel.kallsyms]  [k] alloc_pages_current

We can filter the kernel code and see where in our program we spend most of our time

root@dev-12:# perf report -d hdparm
#
# Events: 64  cpu-clock
#
# Overhead  Command          Symbol
# ........  .......  ..............
#
    90.62%   hdparm  read_big_block
     9.38%   hdparm  time_device

Also by default we use cpu-clock event as the point where we stop to look at our code execution. We can use different events to find out interesting things. For example what are the places in our code that cause page faults:

root@dev-12:# perf record -f -e page-faults -F 100000 hdparm -t /dev/vda > /dev/null
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 0.006 MB perf.data (~278 samples) ]
root@dev-12:# perf report
#
# Events: 87  page-faults
#
# Overhead  Command      Shared Object                    Symbol
# ........  .......  .................  ........................
#
    72.05%   hdparm  hdparm             [.] prepare_timing_buf
    10.96%   hdparm  ld-2.15.so         [.] 0x16b0          
     5.34%   hdparm  libc-2.15.so       [.] 0x86fc0         
     2.53%   hdparm  [kernel.kallsyms]  [k] copy_user_generic_string
     1.26%   hdparm  libc-2.15.so       [.] __ctype_init
     1.26%   hdparm  libc-2.15.so       [.] _IO_vfscanf
     1.26%   hdparm  libc-2.15.so       [.] strchrnul
     1.26%   hdparm  libc-2.15.so       [.] mmap64
     1.26%   hdparm  hdparm             [.] main
     1.26%   hdparm  hdparm             [.] get_dev_geometry
     1.26%   hdparm  [kernel.kallsyms]  [k] __strncpy_from_user
     0.28%   hdparm  [kernel.kallsyms]  [k] __clear_user

To conclude, perf utility is extremely powerful tool. It provides accurate statistics with very little overhead, doesn't require recompilation and can be used to completely understand the overheads of kernel modules and user space application.

What a nice addition to the arsenal of your favorite hacking tools :)