Unusually high dentry cache usage

Problem

A CentOS machine with kernel 2.6.32 and 128 GB physical RAM ran into trouble a few days ago. The responsible system administrator tells me that the PHP-FPM application was not responding to requests in a timely manner anymore due to swapping, and having seen in free that almost no memory was left, he chose to reboot the machine.

I know that free memory can be a confusing concept on Linux and a reboot perhaps was the wrong thing to do. However, the mentioned administrator blames the PHP application (which I am responsible for) and refuses to investigate further.

What I could find out on my own is this:

  • Before the restart, the free memory (incl. buffers and cache) was only a couple of hundred MB.
  • Before the restart, /proc/meminfo reported a Slab memory usage of around 90 GB (yes, GB).
  • After the restart, the free memory was 119 GB, going down to around 100 GB within an hour, as the PHP-FPM workers (about 600 of them) were coming back to life, each of them showing between 30 and 40 MB in the RES column in top (which has been this way for months and is perfectly reasonable given the nature of the PHP application). There is nothing else in the process list that consumes an unusual or noteworthy amount of RAM.
  • After the restart, Slab memory was around 300 MB

If have been monitoring the system ever since, and most notably the Slab memory is increasing in a straight line with a rate of about 5 GB per day. Free memory as reported by free and /proc/meminfo decreases at the same rate. Slab is currently at 46 GB. According to slabtop most of it is used for dentry entries:

Free memory:

free -m
             total       used       free     shared    buffers     cached
Mem:        129048      76435      52612          0        144       7675
-/+ buffers/cache:      68615      60432
Swap:         8191          0       8191

Meminfo:

cat /proc/meminfo
MemTotal:       132145324 kB
MemFree:        53620068 kB
Buffers:          147760 kB
Cached:          8239072 kB
SwapCached:            0 kB
Active:         20300940 kB
Inactive:        6512716 kB
Active(anon):   18408460 kB
Inactive(anon):    24736 kB
Active(file):    1892480 kB
Inactive(file):  6487980 kB
Unevictable:        8608 kB
Mlocked:            8608 kB
SwapTotal:       8388600 kB
SwapFree:        8388600 kB
Dirty:             11416 kB
Writeback:             0 kB
AnonPages:      18436224 kB
Mapped:            94536 kB
Shmem:              6364 kB
Slab:           46240380 kB
SReclaimable:   44561644 kB
SUnreclaim:      1678736 kB
KernelStack:        9336 kB
PageTables:       457516 kB
NFS_Unstable:          0 kB
Bounce:                0 kB
WritebackTmp:          0 kB
CommitLimit:    72364108 kB
Committed_AS:   22305444 kB
VmallocTotal:   34359738367 kB
VmallocUsed:      480164 kB
VmallocChunk:   34290830848 kB
HardwareCorrupted:     0 kB
AnonHugePages:  12216320 kB
HugePages_Total:    2048
HugePages_Free:     2048
HugePages_Rsvd:        0
HugePages_Surp:        0
Hugepagesize:       2048 kB
DirectMap4k:        5604 kB
DirectMap2M:     2078720 kB
DirectMap1G:    132120576 kB

Slabtop:

slabtop --once
Active / Total Objects (% used)    : 225920064 / 226193412 (99.9%)
 Active / Total Slabs (% used)      : 11556364 / 11556415 (100.0%)
 Active / Total Caches (% used)     : 110 / 194 (56.7%)
 Active / Total Size (% used)       : 43278793.73K / 43315465.42K (99.9%)
 Minimum / Average / Maximum Object : 0.02K / 0.19K / 4096.00K

  OBJS ACTIVE  USE OBJ SIZE  SLABS OBJ/SLAB CACHE SIZE NAME                   
221416340 221416039   3%    0.19K 11070817       20  44283268K dentry                 
1123443 1122739  99%    0.41K 124827        9    499308K fuse_request           
1122320 1122180  99%    0.75K 224464        5    897856K fuse_inode             
761539 754272  99%    0.20K  40081       19    160324K vm_area_struct         
437858 223259  50%    0.10K  11834       37     47336K buffer_head            
353353 347519  98%    0.05K   4589       77     18356K anon_vma_chain         
325090 324190  99%    0.06K   5510       59     22040K size-64                
146272 145422  99%    0.03K   1306      112      5224K size-32                
137625 137614  99%    1.02K  45875        3    183500K nfs_inode_cache        
128800 118407  91%    0.04K   1400       92      5600K anon_vma               
 59101  46853  79%    0.55K   8443        7     33772K radix_tree_node        
 52620  52009  98%    0.12K   1754       30      7016K size-128               
 19359  19253  99%    0.14K    717       27      2868K sysfs_dir_cache        
 10240   7746  75%    0.19K    512       20      2048K filp  

VFS cache pressure:

cat /proc/sys/vm/vfs_cache_pressure
125

Swappiness:

cat /proc/sys/vm/swappiness
0

I know that unused memory is wasted memory, so this should not necessarily be a bad thing (especially given that 44 GB are shown as SReclaimable). However, apparently the machine experienced problems nonetheless, and I'm afraid the same will happen again in a few days when Slab surpasses 90 GB.

Questions

I have these questions:

  • Am I correct in thinking that the Slab memory is always physical RAM, and the number is already subtracted from the MemFree value?
  • Is such a high number of dentry entries normal? The PHP application has access to around 1.5 M files, however most of them are archives and not being accessed at all for regular web traffic.
  • What could be an explanation for the fact that the number of cached inodes is much lower than the number of cached dentries, should they not be related somehow?
  • If the system runs into memory trouble, should the kernel not free some of the dentries automatically? What could be a reason that this does not happen?
  • Is there any way to "look into" the dentry cache to see what all this memory is (i.e. what are the paths that are being cached)? Perhaps this points to some kind of memory leak, symlink loop, or indeed to something the PHP application is doing wrong.
  • The PHP application code as well as all asset files are mounted via GlusterFS network file system, could that have something to do with it?

Please keep in mind that I can not investigate as root, only as a regular user, and that the administrator refuses to help. He won't even run the typical echo 2 > /proc/sys/vm/drop_caches test to see if the Slab memory is indeed reclaimable.

Any insights into what could be going on and how I can investigate any further would be greatly appreciated.

Updates

Some further diagnostic information:

Mounts:

cat /proc/self/mounts
rootfs / rootfs rw 0 0
proc /proc proc rw,relatime 0 0
sysfs /sys sysfs rw,relatime 0 0
devtmpfs /dev devtmpfs rw,relatime,size=66063000k,nr_inodes=16515750,mode=755 0 0
devpts /dev/pts devpts rw,relatime,gid=5,mode=620,ptmxmode=000 0 0
tmpfs /dev/shm tmpfs rw,relatime 0 0
/dev/mapper/sysvg-lv_root / ext4 rw,relatime,barrier=1,data=ordered 0 0
/proc/bus/usb /proc/bus/usb usbfs rw,relatime 0 0
/dev/sda1 /boot ext4 rw,relatime,barrier=1,data=ordered 0 0
tmpfs /phptmp tmpfs rw,noatime,size=1048576k,nr_inodes=15728640,mode=777 0 0
tmpfs /wsdltmp tmpfs rw,noatime,size=1048576k,nr_inodes=15728640,mode=777 0 0
none /proc/sys/fs/binfmt_misc binfmt_misc rw,relatime 0 0
cgroup /cgroup/cpuset cgroup rw,relatime,cpuset 0 0
cgroup /cgroup/cpu cgroup rw,relatime,cpu 0 0
cgroup /cgroup/cpuacct cgroup rw,relatime,cpuacct 0 0
cgroup /cgroup/memory cgroup rw,relatime,memory 0 0
cgroup /cgroup/devices cgroup rw,relatime,devices 0 0
cgroup /cgroup/freezer cgroup rw,relatime,freezer 0 0
cgroup /cgroup/net_cls cgroup rw,relatime,net_cls 0 0
cgroup /cgroup/blkio cgroup rw,relatime,blkio 0 0
/etc/glusterfs/glusterfs-www.vol /var/www fuse.glusterfs rw,relatime,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072 0 0
/etc/glusterfs/glusterfs-upload.vol /var/upload fuse.glusterfs rw,relatime,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072 0 0
sunrpc /var/lib/nfs/rpc_pipefs rpc_pipefs rw,relatime 0 0
172.17.39.78:/www /data/www nfs rw,relatime,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,port=38467,timeo=600,retrans=2,sec=sys,mountaddr=172.17.39.78,mountvers=3,mountport=38465,mountproto=tcp,local_lock=none,addr=172.17.39.78 0 0

Mount info:

cat /proc/self/mountinfo
16 21 0:3 / /proc rw,relatime - proc proc rw
17 21 0:0 / /sys rw,relatime - sysfs sysfs rw
18 21 0:5 / /dev rw,relatime - devtmpfs devtmpfs rw,size=66063000k,nr_inodes=16515750,mode=755
19 18 0:11 / /dev/pts rw,relatime - devpts devpts rw,gid=5,mode=620,ptmxmode=000
20 18 0:16 / /dev/shm rw,relatime - tmpfs tmpfs rw
21 1 253:1 / / rw,relatime - ext4 /dev/mapper/sysvg-lv_root rw,barrier=1,data=ordered
22 16 0:15 / /proc/bus/usb rw,relatime - usbfs /proc/bus/usb rw
23 21 8:1 / /boot rw,relatime - ext4 /dev/sda1 rw,barrier=1,data=ordered
24 21 0:17 / /phptmp rw,noatime - tmpfs tmpfs rw,size=1048576k,nr_inodes=15728640,mode=777
25 21 0:18 / /wsdltmp rw,noatime - tmpfs tmpfs rw,size=1048576k,nr_inodes=15728640,mode=777
26 16 0:19 / /proc/sys/fs/binfmt_misc rw,relatime - binfmt_misc none rw
27 21 0:20 / /cgroup/cpuset rw,relatime - cgroup cgroup rw,cpuset
28 21 0:21 / /cgroup/cpu rw,relatime - cgroup cgroup rw,cpu
29 21 0:22 / /cgroup/cpuacct rw,relatime - cgroup cgroup rw,cpuacct
30 21 0:23 / /cgroup/memory rw,relatime - cgroup cgroup rw,memory
31 21 0:24 / /cgroup/devices rw,relatime - cgroup cgroup rw,devices
32 21 0:25 / /cgroup/freezer rw,relatime - cgroup cgroup rw,freezer
33 21 0:26 / /cgroup/net_cls rw,relatime - cgroup cgroup rw,net_cls
34 21 0:27 / /cgroup/blkio rw,relatime - cgroup cgroup rw,blkio
35 21 0:28 / /var/www rw,relatime - fuse.glusterfs /etc/glusterfs/glusterfs-www.vol rw,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072
36 21 0:29 / /var/upload rw,relatime - fuse.glusterfs /etc/glusterfs/glusterfs-upload.vol rw,user_id=0,group_id=0,default_permissions,allow_other,max_read=131072
37 21 0:30 / /var/lib/nfs/rpc_pipefs rw,relatime - rpc_pipefs sunrpc rw
39 21 0:31 / /data/www rw,relatime - nfs 172.17.39.78:/www rw,vers=3,rsize=65536,wsize=65536,namlen=255,hard,proto=tcp,port=38467,timeo=600,retrans=2,sec=sys,mountaddr=172.17.39.78,mountvers=3,mountport=38465,mountproto=tcp,local_lock=none,addr=172.17.39.78

GlusterFS config:

cat /etc/glusterfs/glusterfs-www.vol
volume remote1
  type protocol/client
  option transport-type tcp
  option remote-host 172.17.39.71
   option ping-timeout 10
   option transport.socket.nodelay on # undocumented option for speed
    # http://gluster.org/pipermail/gluster-users/2009-September/003158.html
  option remote-subvolume /data/www
end-volume

volume remote2
  type protocol/client
  option transport-type tcp
  option remote-host 172.17.39.72
   option ping-timeout 10
   option transport.socket.nodelay on # undocumented option for speed
        # http://gluster.org/pipermail/gluster-users/2009-September/003158.html
  option remote-subvolume /data/www
end-volume

volume remote3
  type protocol/client
  option transport-type tcp
  option remote-host 172.17.39.73
   option ping-timeout 10
   option transport.socket.nodelay on # undocumented option for speed
        # http://gluster.org/pipermail/gluster-users/2009-September/003158.html
  option remote-subvolume /data/www
end-volume

volume remote4
  type protocol/client
  option transport-type tcp
  option remote-host 172.17.39.74
   option ping-timeout 10
   option transport.socket.nodelay on # undocumented option for speed
        # http://gluster.org/pipermail/gluster-users/2009-September/003158.html
  option remote-subvolume /data/www
end-volume

volume replicate1
  type cluster/replicate
   option lookup-unhashed off    # off will reduce cpu usage, and network
   option local-volume-name 'hostname'
  subvolumes remote1 remote2
end-volume

volume replicate2
  type cluster/replicate
   option lookup-unhashed off    # off will reduce cpu usage, and network
   option local-volume-name 'hostname'
  subvolumes remote3 remote4
end-volume

volume distribute
  type cluster/distribute
  subvolumes replicate1 replicate2
end-volume

volume iocache
  type performance/io-cache
   option cache-size 8192MB        # default is 32MB
   subvolumes distribute
end-volume

volume writeback
  type performance/write-behind
  option cache-size 1024MB
  option window-size 1MB
  subvolumes iocache
end-volume

### Add io-threads for parallel requisitions
volume iothreads
  type performance/io-threads
  option thread-count 64 # default is 16
  subvolumes writeback
end-volume

volume ra
  type performance/read-ahead
  option page-size 2MB
  option page-count 16
  option force-atime-update no
  subvolumes iothreads
end-volume

Am I correct in thinking that the Slab memory is always physical RAM, and the number is already subtracted from the MemFree value?

Yes.

Is such a high number of dentry entries normal? The PHP application has access to around 1.5 M files, however most of them are archives and not being accessed at all for regular web traffic.

Yes, if the system isn't under memory pressure. It has to use the memory for something, and it's possible that in your particular pattern of usage, this is the best way to use that memory.

What could be an explanation for the fact that the number of cached inodes is much lower than the number of cached dentries, should they not be related somehow?

Lots of directory operations would be the most likely explanation.

If the system runs into memory trouble, should the kernel not free some of the dentries automatically? What could be a reason that this does not happen?

It should, and I can't think of any reason it wouldn't. I'm not convinced that this is what actually went wrong. I'd strongly suggest upgrading your kernel or increasing vfs_cache_pressure further.

Is there any way to "look into" the dentry cache to see what all this memory is (i.e. what are the paths that are being cached)? Perhaps this points to some kind of memory leak, symlink loop, or indeed to something the PHP application is doing wrong.

I don't believe there is. I'd look for any directories with absurdly large numbers of entries or very deep directory structures that are searched or traversed.

The PHP application code as well as all asset files are mounted via GlusterFS network file system, could that have something to do with it?

Definitely it could be a filesystem issue. A filesystem bug causing dentries not to be released, for example, is a possibility.


Confirmed Solution

To anyone who might run into the same problem. The data center guys finally figured it out today. The culprit was a NSS (Network Security Services) library bundled with Libcurl. An upgrade to the newest version solved the problem.

A bug report that describes the details is here:

https://bugzilla.redhat.com/show_bug.cgi?format=multiple&id=1044666

Apparently, in order to determine if some path is local or on a network drive, NSS was looking up a nonexisting file and measureing the time it took for the file system to report back! If you have a large enough number of Curl requests and enough memory, these requests are all cached and stack up.