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/meminforeported 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.