When ps let me down

Some tools have been around for ages helping systems administrators during rough times, making our lives and jobs somewhat easier (ok not all the times xD). One of these marvels is, without a doubt, the almighty ps. What if I told you that ps stole a few hours of my life with no remorse, would you believe me? Well... you should xD.

Situation:

Lets assume you had a Linux system and noticed high system load average, along with unusually high CPU utilization. Having a look at the metrics you realize these had been increasing for a few weeks by now.

A quick glance at top, shows something like this:

top - 20:58:27 up  1:18,  3 users,  load average: 50.27, 29.91, 14.09
Tasks: 20215 total,  13 running, 202 sleeping,   0 stopped, 20000 zombie
%Cpu(s): 29.7 us, 70.0 sy,  0.0 ni,  0.0 id,  0.0 wa,  0.0 hi,  0.3 si,  0.0 st
KiB Mem:   3007548 total,  2584796 used,   422752 free,   214556 buffers
KiB Swap:  1048568 total,        0 used,  1048568 free.   983056 cached Mem

 PID USER      PR  NI    VIRT    RES    SHR S  %CPU %MEM     TIME+ COMMAND
25244 juan      20   0   14228   2180   2060 R  14.1  0.1   0:00.77 ps
25246 juan      20   0   14228   2188   2064 R  13.5  0.1   0:00.70 ps
25248 juan      20   0   14228   2036   1916 R  13.5  0.1   0:00.61 ps
25250 juan      20   0   14228   2100   1976 R  13.5  0.1   0:00.57 ps
25252 juan      20   0   14228   2092   1968 R  13.5  0.1   0:00.49 ps
25254 juan      20   0   14228   2180   2056 R  13.2  0.1   0:00.45 ps
25256 juan      20   0   14228   2092   1968 R  11.5  0.1   0:00.39 ps
23469 root      20   0   47308  20812   2572 R  10.9  0.7   1:18.58 top
25258 juan      20   0   14228   2228   2104 R   9.4  0.1   0:00.32 ps
25260 juan      20   0   14228   2212   2088 R   7.4  0.1   0:00.25 ps
25262 juan      20   0   14228   2040   1916 R   5.0  0.1   0:00.17 ps
25264 juan      20   0   14228   2188   2064 R   2.9  0.1   0:00.10 ps
 2290 juan      20   0 2335644 128804  78096 S   1.2  4.3   0:06.22 skypeforli+
    9 root      20   0       0      0      0 S   0.9  0.0   0:05.64 rcuos/0
   18 root      20   0       0      0      0 S   0.9  0.0   0:04.86 rcuos/1
    7 root      20   0       0      0      0 S   0.6  0.0   0:03.59 rcu_sched
 1071 root      20   0  470184 113424  30860 S   0.6  3.8   0:35.99 Xorg

So, what's wrong with this system?

Well, a bunch of things as you can see:

• To begin with, it kind of looks like an episode of "The Walking Dead", there's 20000 zombie processes xD. Not a big deal, right? zombie processes don't take much memory space and don't cause load increase. However they could easily consume all your process slots within the kernel and that would be a big deal.
• Then system load is literally insane for 2 vCPUs (13 processes in the running queue). 
• Adding up to all that, we have several freaking ps processes taking up to 14% of the CPU time each, how come ps can be taking that much CPU time?

Where do the zombies come from?

Unlike human babies, that we all know are carried by the storks, zombie processes are the result of parent processes not cleaning after their terminated childs (more details here). And in this case, we clearly have a good bunch of them, however in this particular scenario I literally faked the zombie processes so we won't go into details as per why they were created.

Why is the load so freaking high?

The reason for the high load is pretty clear, we have tons of processes in the running queue plus potentially some others in D state blocked by some resources. All these would add up to the system load, and what's concerning is the fact that the load was increasing, so at some point this system would have gone unresponsive.

Why in the world is ps taking so much CPU time?

Having a look at the ps processes, looks as if they were trying to pull the state of a given process:

root@test:/home/juan# ps ha -o state,cmd|grep ps
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
R ps ha -o state,cmd
S grep --color=auto ps
R ps h --pid 3234 -o state
R ps h --pid 3234 -o state
root@test:/home/juan#

A pretty harmless move, you would say, so lets time that operation:

root@test:/home/juan# time ps h --pid 3234 -o state
S

real    0m1.003s
user    0m0.188s
sys     0m0.552s
root@test:/home/juan#

wait..., what? took 1 second to run ps? Which age are we living in?

So ps spent a bit more than half of the time running in kernel space, it also spent about ~200 ms in user space and then somewhere around ~300 ms waiting, maybe in the scheduler queue, maybe IO, maybe all of them, who knows.

Half a second spent in the kernel seems to be a lot for such a simple task "get the process state of PID 3234", right? So what's going on?

Strace to the rescue:

root@test:/home/juan# strace -c ps h --pid 3234 -o state
S
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
 71.16    0.014693         735        20           getdents
 26.54    0.005481           0     40418           read
  1.54    0.000317           0     40423         4 open
  0.47    0.000097           0     40420           close
  0.30    0.000061           0     20210           stat
  0.00    0.000000           0         1           write
  0.00    0.000000           0         6           fstat
  0.00    0.000000           0         2           lseek
  0.00    0.000000           0        16           mmap
  0.00    0.000000           0         7           mprotect
  0.00    0.000000           0         3           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0        23           rt_sigaction
  0.00    0.000000           0         2           ioctl
  0.00    0.000000           0         4         4 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           uname
  0.00    0.000000           0         1           geteuid
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.020649                142959         8 total
root@test:/home/juan#

Turns out it took ps "only 142959 system calls" to get the process state of PID 3234 and that is indeed a pretty insane number of syscalls.

• ~70% of the time in kernel space was consumed by 20 getdents syscalls, these calls were the ones pulling the directory information from /proc. Keep in mind that /proc is a pretty crowded place when there's ~20k process in the system. So despite these calls not being too many, they actually pulled lots of bytes of data (about 600Kbytes, in 32K sized fragments).

root@test:/home/juan# strace -T -e getdents ps h --pid 3234 -o state
getdents(5, /* 1350 entries */, 32768)  = 32768
getdents(5, /* 1365 entries */, 32768)  = 32760
getdents(5, /* 1365 entries */, 32768)  = 32760
getdents(5, /* 1365 entries */, 32768)  = 32760
getdents(5, /* 1365 entries */, 32768)  = 32760
getdents(5, /* 1024 entries */, 32768)  = 32752
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 1024 entries */, 32768)  = 32768
getdents(5, /* 309 entries */, 32768)   = 9888
getdents(5, /* 0 entries */, 32768)     = 0
+++ exited with 1 +++
root@test:/home/juan#

• ~26% of the time was spent on read syscalls (40818 calls), these would effectively be the ones reading data from the files within /proc. 
• The interesting part here is the fact that the number of read, open and close syscalls happen to be almost exactly twice the number of stat calls (20406 calls). And ofcourse the fact that the number of stat calls is alsmot exactly the number of processes in the system.

Wait... are you trying to tell me that ps, despite the fact that you asked for a single process state, is going through all the processes in the system anyways? 

Yeahp, that's exactly what is doing. You don't trust me? (can't blame you, I've been wrong before xD).

That single write syscall in the list above is the one used by ps to show the command output (the process state), right? Ok, so if we dump the strace output to a file we can get a better picture:

root@test:/home/juan# grep ^write -A5 -B5  strace.txt
read(6, "3234 (apache) S 3222 3234 3204 3"..., 1024) = 306
close(6)                                = 0
open("/proc/3234/status", O_RDONLY)     = 6
read(6, "Name:\tapache\nState:\tS (sleeping)"..., 1024) = 780
close(6)                                = 0
fstat(1, {st_mode=S_IFCHR|0620, st_rdev=makedev(136, 4), ...}) = 0
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7ff10e10f000
write(1, "S\n", 2)                      = 2
stat("/proc/3235", {st_mode=S_IFDIR|0555, st_size=0, ...}) = 0
open("/proc/3235/stat", O_RDONLY)       = 6
read(6, "3235 (apache) Z 3234 3234 3234 3"..., 1024) = 162
close(6)                                = 0
open("/proc/3236/status", O_RDONLY)     = 6
root@test:/home/juan#

Clearly ps is going one by one through all the folders available in /proc and once it comes across the one requested by "--pid" it writes the output, however it keeps moving forward untill all folders are checked (this is disturbingly fun when you try it with PID 1).

Now... why would ps do this?

This seems to be a design decition after all. Ps man states:

"ps - report a snapshot of the current processes."

Note: which suggests ps may actually stand for Processes Snapshot (who knows).

"Except as described below, process selection options are additive. The default selection is discarded, and then the selected processes are added to the set of processes to be displayed. A process will thus be shown if it meets any of the given selection criteria."

So what you actually do with the options is descrcibe to ps which processes you want to print out and which information. Then ps will go through all of them and print out the ones that match your description.

Summary

With all these in mind, looks like using ps to get details of a given proces which PID you already know doesn't seem to be efficient at all, and can be a terrible idea in systems hosting a big number of processes.

After all looks like you would be better of reading the state directly from /proc yourself:

root@test:/home/juan# strace -c grep ^State /proc/3234/status
State:  S (sleeping)
% time     seconds  usecs/call     calls    errors syscall
------ ----------- ----------- --------- --------- ----------------
  0.00    0.000000           0         5           read
  0.00    0.000000           0         1           write
  0.00    0.000000           0         6           open
  0.00    0.000000           0         9           close
  0.00    0.000000           0         9           fstat
  0.00    0.000000           0         1         1 lseek
  0.00    0.000000           0        14           mmap
  0.00    0.000000           0         8           mprotect
  0.00    0.000000           0         2           munmap
  0.00    0.000000           0         3           brk
  0.00    0.000000           0         2         1 ioctl
  0.00    0.000000           0         5         5 access
  0.00    0.000000           0         1           execve
  0.00    0.000000           0         1           arch_prctl
  0.00    0.000000           0         1           openat
------ ----------- ----------- --------- --------- ----------------
100.00    0.000000                    68         7 total
root@test:/home/juan#

Only took grep 68 syscalls to retrieve the state of the process :P, yeah I know, now I'm just being a jerk hahaha.

Where do your bytes go when you send them to /dev/null?

I've been playing around with some interesting tools lately so decided to use one of them to answer a rather ontological question. No, I'm not talking about the meaning of life and stuff, but the one on the title!

I'm pretty sure you have at least once come across the idea of running some IO benchmark (I didn't say this is a good idea, but lets face it... you've done it) of your drive and decided to run something like the following:

dd if=/home/juan/myfile of=/dev/null

You know, trying to measure the read throughput of the device where myfile file is stored. Or maybe you've redirected some annoying stderr output to prevent it from showing up on your stdout. The point is that I've always blindly assumed /dev/null is a kind of black hole or one way ticket for your bytes, but never actually understood how it works.

Spoiler alert, I've written this article while working on my Ubuntu Trusty VM, so all the kernel source links will be pointing to kernel 3.19 however, most (if not all) of the code/content should be valid in newer kernels. If it's not valid then, sorry xD I'm not going write this again, so get your hands dirty and read some source code.

What's /dev/null after all?

According to Wikipedia:

The null device is typically used for disposing of unwanted output streams of a process, or as a convenient empty file for input streams. This is usually done by redirection.

Something interesting is the concept of "device", /dev/null isn't a regular file, but a special device file, particularly a character device file. You may have heard the concept of "in Unix everything is a file" (ok, except Network cards :P), that's quite accurate and there are several different file types, being the most common the following:

• Regular files
• Directory
• Named Pipe
• Socket
• Symbolic Link
• Device file
• Character
• Block

Lets have a quick look at this special file and see what's so special about it! Using stat we already have some nice details about it:

juan@test:~$ stat /dev/null
  File: ‘/dev/null’
  Size: 0             Blocks: 0          IO Block: 4096   character special file
Device: 6h/6d    Inode: 1029        Links: 1     Device type: 1,3
Access: (0666/crw-rw-rw-)  Uid: (    0/    root)   Gid: (    0/    root)
Access: 2018-04-17 18:57:48.359574000 +0100
Modify: 2018-04-17 18:57:48.359574000 +0100
Change: 2018-04-17 18:57:48.359574000 +0100
 Birth: -
juan@test:~$

What does "Device type: 1,3"  stand for? Well that's the key here, these two numbers are the Major (identifies the driver used) and the Minor number (identifies the device).

According to Linux Devices documentation, the character device with Major number 1 and Minor Number 3 is the Memory character device /dev/null (aka Null device). If you feel like getting your hands really dirty, you can see the Memory character implementation code here :P.

So what happens when you send stuff to /dev/null?

As with every file intervention, at least the following things have to happen:

- Open the file and get a file descriptor
- Write to the file using the file descriptor obtained previously
- Close the file using the file descriptor obtained previously

these 3 actions require kernel intervention and they map directly to syscalls open, write and close. Lets have a look at this with strace:

root@test:/home/juan# strace -e "open,read,write,close,dup2" dd if=/dev/zero of=/dev/null count=1
open("/etc/ld.so.cache", O_RDONLY|O_CLOEXEC) = 3
close(3)                                = 0
open("/lib/x86_64-linux-gnu/libc.so.6", O_RDONLY|O_CLOEXEC) = 3
read(3, "\177ELF\2\1\1\0\0\0\0\0\0\0\0\0\3\0>\0\1\0\0\0P \2\0\0\0\0\0"..., 832) = 832
close(3)                                = 0
open("/usr/lib/locale/locale-archive", O_RDONLY|O_CLOEXEC) = 3
close(3)                                = 0
open("/dev/zero", O_RDONLY)             = 3
dup2(3, 0)                              = 0
close(3)                                = 0
open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
dup2(3, 1)                              = 1
close(3)                                = 0
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
close(0)                                = 0
close(1)                                = 0
open("/usr/share/locale/locale.alias", O_RDONLY|O_CLOEXEC) = 0
read(0, "# Locale name alias data base.\n#"..., 4096) = 2570
read(0, "", 4096)                       = 0
close(0)                                = 0
open("/usr/share/locale/en_IE/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en_IE/LC_MESSAGES/coreutils.mo", O_RDONLY) = -1 ENOENT (No such file or directory)
open("/usr/share/locale-langpack/en/LC_MESSAGES/coreutils.mo", O_RDONLY) = 0
close(0)                                = 0
write(2, "1+0 records in\n1+0 records out\n", 311+0 records in
1+0 records out
) = 31
write(2, "512 bytes (512 B) copied", 24512 bytes (512 B) copied) = 24
write(2, ", 0.000607882 s, 842 kB/s\n", 26, 0.000607882 s, 842 kB/s
) = 26
close(2)                                = 0
+++ exited with 0 +++
root@test:/home/juan# 

So /dev/null file was opened and in return we got FD 3, which was then copied to FD 1 (dup2(3,1)). Right after this, write call was used to write on it, we can see the exact lines here:

open("/dev/null", O_WRONLY|O_CREAT|O_TRUNC, 0666) = 3
dup2(3, 1)                              = 1
close(3)                                = 0
read(0, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512
write(1, "\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0\0"..., 512) = 512

Once the process hands over control to the kernel to execute the syscalls code we totally loose track of what's going on. To be honest that's the whole point of an API like the syscall layer, however sometimes is good to have the chance to see how things work in the background, and in order to answer the question we need to understand it.

Ftrace, like strace but way more fun!

Ftrace was introduced on the Linux kernel long ago, somewhere around late 2008 on Kernel 2.6.27. It allows users to trace certain Kernel functions given an incredible visibility of what's going and how things really work.

In order for ftrace to be available, the kernel needs to be compiled with this tracing feature. You can confirm by looking for CONFIG_FUNCTION_TRACER, like:

juan@test:~$ grep FUNCTION_TRACER /boot/config-3.19.0-51-generic
CONFIG_HAVE_FUNCTION_TRACER=y
CONFIG_FUNCTION_TRACER=y
juan@test:~$

Many distributions ship their kernels with ftrace enabled and even the debugfs (the way to access ftrace data) file system mounted (Ubuntu for example):

juan@test:~$ mount | grep debug
none on /sys/kernel/debug type debugfs (rw)
juan@test:~$

What essentially happens is pretty much summed up in these lines:

It uses a compiler feature to insert a small, 5-byte No-Operation instruction to the beginning of every kernel function, which NOP sequence is then dynamically patched into a tracer call when tracing is enabled by the administrator. 

so these few extra bytes are used later on to hook a tracing function that will gather the details of the invoked functions, pretty neat!

There's a LOT of ftrace documentation around so I won't waste time repeating any of it. I do suggest you to read it though. In this particular case I'll be using trace-cmd frontend tool instead of directly use the files under the debugfs directory.

BTW: ftrace is a great way to inspect and learn about the Linux Kernel, so do give it a go.

SHOW ME THE MONEY!

Ok, ok,... In order to track the kernel functions I'm going to use function_graph plugin with a little of filtering to only get the events related to the write syscall:

root@test:/home/juan# trace-cmd record -p function_graph -g "SyS_write" dd if=/dev/zero of=/dev/null count=1
  plugin 'function_graph'
1+0 records in
1+0 records out
512 bytes (512 B) copied, 0.00255381 s, 200 kB/s
Kernel buffer statistics:
  Note: "entries" are the entries left in the kernel ring buffer and are not
        recorded in the trace data. They should all be zero.

CPU: 0
entries: 0
overrun: 0
commit overrun: 0
bytes: 2476
oldest event ts: 180098.264687
now ts: 180098.267521
dropped events: 0
read events: 468

CPU: 1
entries: 0
overrun: 0
commit overrun: 0
bytes: 2184
oldest event ts: 180098.266223
now ts: 180098.267677
dropped events: 0
read events: 1882

CPU0 data recorded at offset=0x42b000
    20480 bytes in size
CPU1 data recorded at offset=0x430000
    77824 bytes in size
root@test:/home/juan# 

The execution of the command creates a "trace.dat" file were the captured events are written. Then you can access to these events using "trace-cmd report". Since we know we are looking for the first Write call done by dd command I will limit the output of the report to the following:

root@test:/home/juan# trace-cmd report | grep "dd-" | head -25
              dd-3770  [001] 180098.263240: funcgraph_entry:                   |  SyS_write() {
              dd-3770  [001] 180098.263269: funcgraph_entry:                   |    __fdget_pos() {
              dd-3770  [001] 180098.263269: funcgraph_entry:        0.077 us   |      __fget_light();
              dd-3770  [001] 180098.263270: funcgraph_exit:         0.669 us   |    }
              dd-3770  [001] 180098.263270: funcgraph_entry:                   |    vfs_write() {
              dd-3770  [001] 180098.263270: funcgraph_entry:                   |      rw_verify_area() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |        security_file_permission() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |          apparmor_file_permission() {
              dd-3770  [001] 180098.263271: funcgraph_entry:                   |            common_file_perm() {
              dd-3770  [001] 180098.263272: funcgraph_entry:        0.087 us   |              aa_file_perm();
              dd-3770  [001] 180098.263272: funcgraph_exit:         0.679 us   |            }
              dd-3770  [001] 180098.263272: funcgraph_exit:         1.230 us   |          }
              dd-3770  [001] 180098.263273: funcgraph_exit:         1.783 us   |        }
              dd-3770  [001] 180098.263273: funcgraph_exit:         2.330 us   |      }
              dd-3770  [001] 180098.263273: funcgraph_entry:        0.068 us   |      write_null();
              dd-3770  [001] 180098.263274: funcgraph_entry:                   |      __fsnotify_parent() {
              dd-3770  [001] 180098.263274: funcgraph_entry:        0.103 us   |        dget_parent();
              dd-3770  [001] 180098.263275: funcgraph_entry:        0.078 us   |        dput();
              dd-3770  [001] 180098.263275: funcgraph_exit:         1.255 us   |      }
              dd-3770  [001] 180098.263276: funcgraph_entry:                   |      fsnotify() {
              dd-3770  [001] 180098.263276: funcgraph_entry:        0.308 us   |        __srcu_read_lock();
              dd-3770  [001] 180098.263277: funcgraph_entry:        0.087 us   |        __srcu_read_unlock();
              dd-3770  [001] 180098.263277: funcgraph_exit:         1.548 us   |      }
              dd-3770  [001] 180098.263278: funcgraph_exit:         7.318 us   |    }
              dd-3770  [001] 180098.263278: funcgraph_exit:         9.498 us   |  }
root@test:/home/juan#

Pretty neat, right? we can clearly see the entry and exit of "every" kernel function within the SyS_write syscall. Now, with the function names we can go to our one and only https://elixir.bootlin.com and read the code of each function to have a better picture:

• SyS_write Write syscall enter
• vfs_write VFS generic write path, security checks and permissions validation (among other things :))
•  write_null this function is the write function for the specific device /dev/null (indicated by the file_operations structure of the device), if this was a regular file we would see here a File System specific write function.

Now if we explore the code of write_null, we can see the following:

static ssize_t write_null(struct file *file, const char __user *buf,
     size_t count, loff_t *ppos)
{
 return count;
}

the parameters:

• *file the file structure (created during the open syscall and linked to the fd)
• *buf the buffer that keeps the data that is supposed to be written
• count the number of bytes to write 
• *ppos the position within the file where to start writing. 

As you can see the function itself doesn't do a thing (which was kind of expected after all xD), it just returns the number of bytes that were supposed to be written as some sort of acknowledgement and confirming the write operation did actually take place.

So not only now you know about /dev/null :P but you can go and have fun with ftrace exploring the Linux Kernel!!!

To answer the question, your bytes literally go nowhere!

Processes in uninterruptable state (D) - What to do with them?

On the previous entry a I talked about the infamous zombie state and how they just can't be killed. Now is time to some even more scary than the Z state, [suspense sounds].... the D state [/suspense sounds].

As its name precisely suggests, processes in uninterruptible state (D in ps/top/etc) cannot be interrupted hence they can't be killed either!!! An unlike a process Z state, the former might be indeed occupying memory you can't get back!

How do you get into D state?

Most of the time people associates processes in D state with IO activity, and that's not wrong actually that's exactly what man ps says:

PROCESS STATE CODES
       Here are the different values that the s, stat and state output specifiers (header "STAT" or "S") will display to describe the state of a
       process:

               D    uninterruptible sleep (usually IO)
               R    running or runnable (on run queue)
               S    interruptible sleep (waiting for an event to complete)
               T    stopped, either by a job control signal or because it is being traced
               W    paging (not valid since the 2.6.xx kernel)
               X    dead (should never be seen)
               Z    defunct ("zombie") process, terminated but not reaped by its parent

However processes that go into D state due to IO usually come back to R once the IO operation that was holding them is completed (unless something goes nuts). Now, there are some scenarios that don't involve IO and can also lead to D state, for example when using serialization mechanisms like mutexes. When you try to acquire a mutex that has been locked already you have two options, either you go into interruptable sleep (S) or you go into uninterruptible sleep (D) this is something that will depend on what the code is supposed to do and whether you want to be able to receive signals and stuff while waiting for the mutex to be available. If you are curious about mutexes in the kernel have a look at this or a shorter and perhaps more human version here.

So how do you detect a process in D state?

That's rather simple! You can use the regular tools like ps and top and look for the State field/column. For example:

juan@test:~$ ps aux|grep test
root     20592  0.0  0.0   4220   656 pts/2    S+   21:36   0:00 ./test
root     20593  0.0  0.0   4216   640 pts/24   D+   21:36   0:00 ./test
juan     20982  0.0  0.0  15964  2268 pts/27   R+   23:26   0:00 grep --color=auto test
juan@test:~$

in this case, process 20593 is in D+ state, so Uninterruptable sleep and is a foreground process.

What to do with a process in D state? How to know what is actually locking the process:

This is where things get interesting. As I mentioned before D state is usually temporary and most of the times if you see a process in that state as soon as you run ps again the process will have changed to either R or S. BUT... if you believe the process is just refusing to leave D state, then what to do?

Lots of people answer this question with "I kill the process"... well that's exactly why is called UNinterruptible, it will absolutely ignore your most violent attempts to kill it. Any signals you send to the process will be queued and delivered eventually once the process leaves the D state, if it ever does of course.

Fortunately there are a few things that can help you debug this lovely situation and prevent it from happening in the future.

Have a look at the process stack:

This would be an initial approach, by having a look at the process stack you can get an idea of what code path took the process to that D condition. Luckily having a look at the stack isn't that hard now a days and you can do that by using /proc/:

juan@test:~$ sudo cat /proc/20593/stack
[<ffffffffc04ee045>] dev_open+0x15/0x40 [ebbcharmutex]
[<ffffffff811f0a7f>] chrdev_open+0x9f/0x1d0
[<ffffffff811e9527>] do_dentry_open+0x1f7/0x340
[<ffffffff811ead87>] vfs_open+0x57/0x60
[<ffffffff811faccc>] do_last+0x4ec/0x1190
[<ffffffff811fb9f0>] path_openat+0x80/0x600
[<ffffffff811fd10a>] do_filp_open+0x3a/0x90
[<ffffffff811eb109>] do_sys_open+0x129/0x280
[<ffffffff811eb27e>] SyS_open+0x1e/0x20
[<ffffffff817b788d>] system_call_fastpath+0x16/0x1b
[<ffffffffffffffff>] 0xffffffffffffffff
juan@test:~$

nice! So the process is locked in Kernel space and started by running an open syscall (SyS_Open+0x1e/0x20) on some sort of character device (chrdev_open+0x9f/0x1d0) and there's a module intervening here called [ebbcharmutex]. Since this is a stack trace we know with high certainty that the process is blocked particularly inside dev_open call, and that the code for the function belongs to module ebbcharmutex.
For more details about ebbcharmutex, I'd suggest to go to the source (really nice website around Linux and embedded systems) anyways here a piece of the code:

/** @brief The device open function that is called each time the device is opened
 *  This will only increment the numberOpens counter in this case.
 *  @param inodep A pointer to an inode object (defined in linux/fs.h)
 *  @param filep A pointer to a file object (defined in linux/fs.h)
 */
static int dev_open(struct inode *inodep, struct file *filep){

//   if(!mutex_trylock(&ebbchar_mutex)){                  // Try to acquire the mutex (returns 0 on fail)
//      printk(KERN_ALERT "EBBChar: Device in use by another process");
//      return -EBUSY;
//  }
   mutex_lock(&ebbchar_mutex);
   numberOpens++;
   printk(KERN_INFO "EBBChar: Device has been opened %d time(s)\n", numberOpens);
   return 0;
}

as you can see the very first line of the function calls mutex_lock() in its uninterrtible fashion hence this is where our process is stuck.

Now what? well... technically there's not much you can do to unlock the process, all you can try to do is identify who could be the one holding the lock and not releasing it (of course this would require some serious understanding of the problem and the code itself). In my simple case scenario you can see that I had two test processes one of them in S+ state (scroll up, I'm not going to paste it twice :P), if we check the opened files for that process we can see it opened /dev/ebbchar so he is the one holding the lock:

root@test:/home/juan# lsof -p 20592
COMMAND   PID USER   FD   TYPE DEVICE SIZE/OFF   NODE NAME
test    20592 root  cwd    DIR    8,1     4096 466847 /home/juan/ModTest/exploringBB/extras/kernel/ebbcharmutex
test    20592 root  rtd    DIR    8,1     4096      2 /
test    20592 root  txt    REG    8,1     9102 466927 /home/juan/ModTest/exploringBB/extras/kernel/ebbcharmutex/test
test    20592 root  mem    REG    8,1  1857312 583879 /lib/x86_64-linux-gnu/libc-2.19.so
test    20592 root  mem    REG    8,1   149120 583895 /lib/x86_64-linux-gnu/ld-2.19.so
test    20592 root    0u   CHR  136,2      0t0      5 /dev/pts/2
test    20592 root    1u   CHR  136,2      0t0      5 /dev/pts/2
test    20592 root    2u   CHR  136,2      0t0      5 /dev/pts/2
test    20592 root    3u   CHR  250,0      0t0  69224 /dev/ebbchar
root@test:/home/juan#

If you can't really understand why the process isn't releasing the lock, since it is in S+ state, you can kill it and this should free the lock hence releasing the other stuck process:

root@test:/home/juan# kill -9 20592
root@test:/home/juan# ps aux|grep test
root     20593  0.0  0.0   4220   640 pts/24   S+   05:39   0:00 ./test
root     21460  0.0  0.0  15964  2140 pts/26   S+   12:06   0:00 grep --color=auto test
root@test:/home/juan#

perfect, now process 20593 is in S state!

The kernel doesn't like processes in D state either:

Can't blame it, right? Long time in D state is usually sign of some kind of issue, either high load or locking problems. Because of this, the kernel has 4 features to detect and act on processes in D state. Here you can see the default setup for Ubuntu:

root@test:/home/juan# cat /proc/sys/kernel/hung_task_timeout_secs
120
root@test:/home/juan# cat /proc/sys/kernel/hung_task_panic
0
root@test:/home/juan# cat /proc/sys/kernel/hung_task_check_count
4194304
root@test:/home/juan# cat /proc/sys/kernel/hung_task_warnings
0
root@test:/home/juan#

What do these values mean (for more precision read this):

• hung_task_timeout_secs: if a task doesn't get scheduled in more than that number of seconds a warning will be reported.
• hung_task_panic: to indicate the kernel whether it should panic or not when detecting a hung task. 0 for no panic, 1 for panic. This for example could be use to reboot the system.
• hung_task_check_count: maximum number of tasks to be checked, don't really get this one...
• hung_task_warnings: maximum number of warnings due to hung tasks to be reported, every time a task is detected as hung this number gets decreased, when reaching 0 no more reports will be issued.

 How does a warning report look like? Oh.. they are lovely:

Dec 20 19:57:25 test kernel: [78751.283729] INFO: task test:20593 blocked for more than 120 seconds.
Dec 20 19:57:25 test kernel: [78751.283737]       Tainted: G           OE  3.19.0-51-generic #58~14.04.1-Ubuntu
Dec 20 19:57:25 test kernel: [78751.283739] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
Dec 20 19:57:25 test kernel: [78751.283741] test            D ffff88003610bb68     0 20593  18722 0x00000000
Dec 20 19:57:25 test kernel: [78751.283748]  ffff88003610bb68 ffff88007ce9f5c0 0000000000013e80 ffff88003610bfd8
Dec 20 19:57:25 test kernel: [78751.283753]  0000000000013e80 ffff8800b771f5c0 ffff88007ce9f5c0 ffff88007ce9f5c0
Dec 20 19:57:25 test kernel: [78751.283756]  ffffffffc04f0100 ffffffffc04f0104 ffff88007ce9f5c0 00000000ffffffff
Dec 20 19:57:25 test kernel: [78751.283760] Call Trace:
Dec 20 19:57:25 test kernel: [78751.283773]  [<ffffffff817b3a29>] schedule_preempt_disabled+0x29/0x70
Dec 20 19:57:25 test kernel: [78751.283778]  [<ffffffff817b5745>] __mutex_lock_slowpath+0x95/0x100
Dec 20 19:57:25 test kernel: [78751.283781]  [<ffffffff817b57b5>] ? mutex_lock+0x5/0x37
Dec 20 19:57:25 test kernel: [78751.283785]  [<ffffffff817b57d3>] mutex_lock+0x23/0x37
Dec 20 19:57:25 test kernel: [78751.283790]  [<ffffffffc04ee045>] ? dev_open+0x15/0x40 [ebbcharmutex]
Dec 20 19:57:25 test kernel: [78751.283793]  [<ffffffffc04ee045>] dev_open+0x15/0x40 [ebbcharmutex]
Dec 20 19:57:25 test kernel: [78751.283798]  [<ffffffff811f0a7f>] chrdev_open+0x9f/0x1d0
Dec 20 19:57:25 test kernel: [78751.283802]  [<ffffffff811e9527>] do_dentry_open+0x1f7/0x340
Dec 20 19:57:25 test kernel: [78751.283805]  [<ffffffff811f09e0>] ? cdev_put+0x30/0x30
Dec 20 19:57:25 test kernel: [78751.283808]  [<ffffffff811ead35>] ? vfs_open+0x5/0x60
Dec 20 19:57:25 test kernel: [78751.283812]  [<ffffffff811ead87>] vfs_open+0x57/0x60
Dec 20 19:57:25 test kernel: [78751.283815]  [<ffffffff811faccc>] do_last+0x4ec/0x1190
Dec 20 19:57:25 test kernel: [78751.283820]  [<ffffffff811fb9f0>] path_openat+0x80/0x600
Dec 20 19:57:25 test kernel: [78751.283825]  [<ffffffff810a6ef5>] ? update_stats_wait_end+0x5/0xd0
Dec 20 19:57:25 test kernel: [78751.283828]  [<ffffffff817b38b5>] ? _cond_resched+0x5/0x40
Dec 20 19:57:25 test kernel: [78751.283832]  [<ffffffff811fd10a>] do_filp_open+0x3a/0x90
Dec 20 19:57:25 test kernel: [78751.283836]  [<ffffffff81209cd7>] ? __alloc_fd+0xa7/0x130
Dec 20 19:57:25 test kernel: [78751.283839]  [<ffffffff811fd0d5>] ? do_filp_open+0x5/0x90
Dec 20 19:57:25 test kernel: [78751.283843]  [<ffffffff811eb109>] do_sys_open+0x129/0x280
Dec 20 19:57:25 test kernel: [78751.283846]  [<ffffffff811eafe5>] ? do_sys_open+0x5/0x280
Dec 20 19:57:25 test kernel: [78751.283850]  [<ffffffff811eb27e>] SyS_open+0x1e/0x20
Dec 20 19:57:25 test kernel: [78751.283853]  [<ffffffff817b788d>] system_call_fastpath+0x16/0x1b

The report provides an even more detailed stack trace along with some other details. Now, if you have a look at the top of the stack trace becomes crystal clear the fact that the process is stuck trying to acquire a lock a mutex.

Summing this up:

Processes in D state are rare and could be an indication of system issues like intense IO, high load, or maybe locking problems. Because of being uninterruptible, they don't get to be scheduled hence signals can't be delivered so the process can't be killed. Fortunately there are a few things you can do in order to gather more information to have the chance to troubleshoot the problem.

Some Zombies just can't be killed - Zombie Processes

We've been told by so many movies and TV series that no matter how smelly or ugly Zombies can be, you can easily kill them by either blowing up their heads with a shotgun or gently detaching it from the rest of the body (this doesn't really kill the zombie but renders it almost harmless, fun fact, head can't run while detached from the legs). Unfortunately Zombie processes don't really follow the previous "Zombie expected" behavior and they just can't be killed (kill -9 PID).

What in the world is a Zombie process?

Wikipedia has a pretty nice description here, but essentially we are talking about a process that has finished its execution through either exit or exit_group syscalls but remains present in the system due to some unfinished housekeeping tasks. You can easily identify a zombie process from its Z state in for example top or ps. A nice description can be found here the wait man page:

       A child that terminates, but has not been waited for becomes a
       "zombie".  The kernel maintains a minimal set of information about
       the zombie process (PID, termination status, resource usage
       information) in order to allow the parent to later perform a wait to
       obtain information about the child.  As long as a zombie is not
       removed from the system via a wait, it will consume a slot in the
       kernel process table, and if this table fills, it will not be
       possible to create further processes.  If a parent process
       terminates, then its "zombie" children (if any) are adopted by
       init(1), (or by the nearest "subreaper" process as defined through
       the use of the prctl(2) PR_SET_CHILD_SUBREAPER operation); init(1)
       automatically performs a wait to remove the zombies.

For some reason there's a lot of confusion around this Z state, for example:

• Orphan processes aren't zombie processes, in fact for a process to become zombie its parent process has to be still alive. If the parent dies it will be adopted by init and waitED properly.
•  A Zombie process isn't consuming memory (or CPU), to be more precise, isn't consuming as much memory as it was consuming while it was running. However it still occupies a slot in the process table and this could be a problem.

 What happens when exit or exit_group are called?

As I mentioned before these are the syscalls used to terminate a process gracefully. You can find the details of these two for kernel 4.14 here and here. I'm not going to describe the whole code because first I don't understand all of it and second I would probably do it wrong :), but... I'm going to point out some interesting parts:

• Things begin in do_group_exit which takes care of killing all the threads in the current process thread group then it calls do_exit to finish the process itself.
• do_exit takes care of a few things as well, for example releasing some of the resources associated to the process like files and shared memory (lines 858-866). Later on in line 885, calls to exit_notify, which is in charge of sending to the relative processes the bad news, kind of "Hey!, I'm dying" thing. Now within this function a few things will happen being the most important ones the following:
• do_notify_parent will be called to signal the parent process with a SIGCHLD signal. This function will return either true or false depending on whether the dying process should become a Zombie or just go regular dead.
• Have a look at the comment in here, long story short, IF the father decides to ignore (by setting the handler to SIG_IGN) the SIGCHLD signal (or SA_NOCLDWAIT flag is set) the dying process can reap itself and doesn't become a zombie and in that case do_notify_parent will return true. Otherwise it will return false.
• Back to exit_notify, you can see in here how the process decides whether or not to become a zombie depending on the autoreap variable.

Something worth mentioning is the fact that Zombie is an exit state (tsk ->exit_state) while the scheduling state of the process is actually Dead, you can see this is defined by calling here do_task_dead function. So a Zombie process isn't consuming CPU resources at all, for the scheduling perspective this process is gone, and so it is all the other resources that had been allocated to it.

Why can't it be killed?

Well, you can still send SIGKILL signal to a Zombie process and as you may know, you can't escape from that signal. However technically speaking even though the process is still in the process table, there's nothing it can do, there's no code attached to it anymore, no stack, no files, nothing.

Example

Lets have a look at all this zombie stuff with a simple example. You can get the code here, it's a simple C program that will fork 2 child processes and allocate some memory in each. The parent will sleep for 30 seconds, while the child processes will wait for 15 seconds, hence dying while the father is still running (sleeping) becoming spoooky zombiesssss:

juan@test:~$gcc -o zombie_maker zombie_maker.c
juan@test:~$ ./zombie_maker &
juan@test:~$ Parent PID = 2050, PGRP = 2050, PPID = 1934, PSID = 1934
Child 0 -> PID = 2051, PGRP = 2050, PPID = 2050, PSID = 1934
Child 1 -> PID = 2052, PGRP = 2050, PPID = 2050, PSID = 1934

juan@test:~$ ps aux|grep zombie
juan      2050  0.0  0.0   4216   732 pts/1    S    21:34   0:00 ./zombie_maker
juan      2051  0.0  0.0   6268    92 pts/1    S    21:34   0:00 ./zombie_maker
juan      2052  0.0  0.0   6268    92 pts/1    S    21:34   0:00 ./zombie_maker
juan      2054  0.0  0.0  15960  2268 pts/1    R+   21:34   0:00 grep --color=auto zombie
juan@test:~$ ps aux|grep zombie
juan      2050  0.0  0.0   4216   732 pts/1    S    21:34   0:00 ./zombie_maker
juan      2051  0.0  0.0      0     0 pts/1    Z    21:34   0:00 [zombie_maker] 
juan      2052  0.0  0.0      0     0 pts/1    Z    21:34   0:00 [zombie_maker] 
juan      2056  0.0  0.0  15960  2268 pts/1    S+   21:34   0:00 grep --color=auto zombie
juan@test:~$ ps aux|grep zombie
juan      2058  0.0  0.0  15960  2288 pts/1    S+   21:35   0:00 grep --color=auto zombie
[2]+  Done                    ./zombie_maker
juan@test:~$

After the 15 second, we can see how both child processes not only became Zombies but they also show no memory footprint whatsoever on the system (VSZ is 0 and RSS is 0 as well). After the 30 seconds we can see that none of the 3 processes exist anymore, but who reaped the Zombie children from the system???

Yeahp, init did! Attaching to init with strace we can see the waitid calls returning with the details from the Zombie processes:

root@test:/home/juan# strace -p 1
Process 1 attached
select(54, [3 5 6 7 10 11 15 16 17 19 20 24 26 30 34 53], [], [7 10 11 15 16 17], NULL) = ? ERESTARTNOHAND (To be restarted if no handler)
...
waitid(P_ALL, 0, {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2051, si_status=3, si_utime=0, si_stime=0}, WNOHANG|WEXITED|WSTOPPED|WCONTINUED, NULL) = 0
waitid(P_ALL, 0, {si_signo=SIGCHLD, si_code=CLD_EXITED, si_pid=2052, si_status=3, si_utime=0, si_stime=0}, WNOHANG|WEXITED|WSTOPPED|WCONTINUED, NULL) = 0
select(54, [3 5 6 7 10 11 15 16 17 19 20 24 26 30 34 53], [], [7 10 11 15 16 17], NULL^CProcess 1 detached
 
root@test:/home/juan#

Running zombie_maker with strace will show you how the parent process gets indeed interrupted by the SIGCHLD signals but since the handler isn't defined it is ignored. PLEASE, don't confuse that ignore with the one that happens when the handler is set to SIG_IGN, literally this is what the documentation says:

       POSIX.1-2001 specifies that if the disposition of SIGCHLD is set to
       SIG_IGN or the SA_NOCLDWAIT flag is set for SIGCHLD (see
       sigaction(2)), then children that terminate do not become zombies and
       a call to wait() or waitpid() will block until all children have
       terminated, and then fail with errno set to ECHILD.  (The original
       POSIX standard left the behavior of setting SIGCHLD to SIG_IGN
       unspecified.  Note that even though the default disposition of
       SIGCHLD is "ignore", explicitly setting the disposition to SIG_IGN
       results in different treatment of zombie process children.)

Summary

No matter how brave or root you are, you can't kill a Zombie process :D, killing its parent is usually the way to get rid of them. When the parent dies, init will adopt the little zombie bastards and reap them off the process table, as we saw on the example. Also as mentioned, a Zombie process doesn't consume much system resources (actually almost none), so unless you have hundreds of them you shouldn't worry much.

The kernel code is going crazy, it would be nice if we had more comments in place :P.

We all understand free command... don't we???

I know I should be writing the next entry of "Understanding SOMAXCONN parameter Part I" (and I am) but instead I decided to do a little detour first. I faced this question about free a few days ago and noticed odd/different answers for it (including my own xD) so decided to go for a deep dive and found some interesting facts worth sharing.

Free

Free Linux command is one of those tools you will be definitely get exposed to as a sysadmin, and understanding its output is extremely important. A bad interpretation of free output could cause unnecessary panic and you don't want to panic for no reason :D (oh wait... maybe you do, I certainly don't ).

Lets have a look at a simple free output:

juan@test:~$ free
             total       used       free     shared    buffers     cached
Mem:       3007572     584872    2422700      14780      55808     291704
-/+ buffers/cache:     237360    2770212
Swap:            0          0          0
juan@test:~$

In the line starting with "Mem:" we get to see the total available physical memory on the system 3007572 KBytes (3GBytes) and then how it is distributed:

• used: memory being occupied
• free: memory that is available in the system
• shared: amount of memory that is shared between processes
• buffers: memory used for kernel buffers involving IO (disk, network, etc)
• cached: memory used for data caching

Then we have a line starting with "-/+ buffers/cache:" which looks kind of cryptic, doesn't it?... it turns out to be a kind of summary of the previous line:

• There are 237360 KBytes being used, this number is the result of the following math "used - (buffers + cached)". This is the amount of memory the system is actually relying on.
• There are 2770212 KBytes that could be utilized, this is the result of "free + buffers + cached". What this number actually means is that the kernel should be able to reclaim buffer and cached memory if necessary.

So we have a better understanding of free output now, but lets get more details of where these numbers come from.

The power of the force source

Free binary is shipped as part of procps-ng package in Linux and we can inspect its latest code here. What free actually does for you is summarize memory utilization details coming from /proc/meminfo in a more "human way". So lets dissect this...

• The main source code can be read here free.c, if you have a look at the lines between 359-377, you can see that there are 6 variables kb_main_total, kb_main_used, kb_main_free, kb_main_shared, kb_main_buffers and kb_main_cached and they are actually the ones containing the values that will show up in free's output. However if you look for these variables on the code you won't find them, they are extern variables included from "proc/sysinfo.h" which means the variables are being initialized somewhere else, particularly in "proc/sysinfo.c". The variables are actually being populated by meminfo() function being called in line 355.

  meminfo();
  /* Translation Hint: You can use 9 character words in
   * the header, and the words need to be right align to
   * beginning of a number. */
  if (flags & FREE_WIDE) {
   printf(_("              total        used        free      shared     buffers       cache   available"));
  } else {
   printf(_("              total        used        free      shared  buff/cache   available"));
  }
  printf("\n");
  printf("%-7s", _("Mem:"));
  printf(" %11s", scale_size(kb_main_total, flags, args));
  printf(" %11s", scale_size(kb_main_used, flags, args));
  printf(" %11s", scale_size(kb_main_free, flags, args));
  printf(" %11s", scale_size(kb_main_shared, flags, args));
  if (flags & FREE_WIDE) {
   printf(" %11s", scale_size(kb_main_buffers, flags, args));
   printf(" %11s", scale_size(kb_main_cached, flags, args));
  } else {
   printf(" %11s", scale_size(kb_main_buffers+kb_main_cached, flags, args));
  }
  printf(" %11s", scale_size(kb_main_available, flags, args));
  printf("\n");

• Now checking the "proc/sysinfo.c" code where meminfo() function exists, we see:
• kb_main_buffer is populated with the content of Buffers value from /proc/meminfo (line 691), this is memory used by the kernel to temporarily hold data being sent/received by the system (network IO, disk IO, etc).
• kb_main_cached is populated with the result of "kb_page_cache + kb_slab_reclaimable" (line 762). These two values come from Cached and SReclaimable respectively (in /proc/meminfo). So the cached value presented by free contains the memory used by the page cache and the reclaimable slab memory (slab memory caches dentry and inodes structures to speed up some fs operations).

  {"Bounce",       &kb_bounce},
  {"Buffers",      &kb_main_buffers}, // important
  {"Cached",       &kb_page_cache},  // important
  {"CommitLimit",  &kb_commit_limit},
  ...
  kb_main_cached = kb_page_cache + kb_slab_reclaimable;
  kb_swap_used = kb_swap_total - kb_swap_free;

It is clear now that free relies completely on the details exposed by the kernel through /proc/meminfo, and the math involved in getting the values isn't really rocket science after all. But here it comes the interesting part...

To have in mind

It looks like the information provided by free can be slightly different between different Linux flavors (because they carry different free versions :D) so I thought it might be worth pointing that out here as well. This could lead to some inconsistencies when some other tools rely on the output of free.

Free version shipped with Ubuntu 14.04 (3.3.9), doesn't even include Slabs under the cached memory, you can see here how kb_main_cached value is just populated with Cached value from /proc/meminfo.

juan@test:~$ free -V
free from procps-ng 3.3.9
juan@test:~$ free
             total       used       free     shared    buffers     cached
Mem:       3007572     530948    2476624      14776      53080     244740
-/+ buffers/cache:     233128    2774444
Swap:            0          0          0
juan@test:~$ grep "^Cached\|^SReclaimable\|^Slab" /proc/meminfo
Cached:           244740 kB
Slab:              32308 kB
SReclaimable:      17572 kB
juan@test:~$

Note: cached = Cached

Free version shipped with CentOS 7 (3.3.10), defines kb_main_cached as "kb_page_cache + kb_slab" (706) this seems a minor thing but not all the slab memory is reclaimable therefore part of this cached content is not really available in case of memory pressure.

[juan@server ~]$ free -V
free from procps-ng 3.3.10
[juan@server ~]$ free -w
              total        used        free      shared     buffers       cache   available
Mem:        1016860       74212      818380        6688         948      123320      810600
Swap:             0           0           0
[juan@server ~]$ grep "^Cached\|^SRecl\|^Slab" /proc/meminfo
Cached:            88876 kB
Slab:              34444 kB
SReclaimable:      13928 kB
[juan@server ~]$

Note: cache = Cached + Slab

Interesting, isn't it? That's the power of open source after all right? Having the chance to really understand what certain piece of software is doing for you and how is doing it!

That's all about free, hope it helps (it helped me at least :P).

Understanding SOMAXCONN parameter Part I

This post is kind of a fork of something I worked on the previous week and tries to shed some light on what somaxconn parameter means in the context of Linux Network stack. I've tried to prepare something similar to what I did in TCP Keep Alive - how it works, with examples and some traffic captures so I guess this article will be a bit longer that [I|you]'d like xD, but useful (hopefully).

somaxconn

By definition this value is the maximum number of established connections a socket may have queuing waiting to be accepted by the process holding the socket. This is completely different from tcp_syn_max_backlog since this value is for incomplete connection (connections that haven't been ACKed yet).

To give more context to that statement is necessary to understand a bit more about sockets. When a socket is created, before being able to receive connections two things must happen:

1. It has to be bind() to a local address.
2. It has to bet set to listen() for connections.

The listen() syscall is key here, it receives 2 parameters:

• the file descriptor that describes the socket (remember "A file descriptor is a data structure used by processes to access: files, Unix sockets, Networking sockets, pipes, etc").
• the backlog value. This integer defines the size of the socket queue for established connections waiting to be accepted... yeah :D same as somaxconn. This backlog parameter cannot be bigger than somaxconn and in fact if it is bigger, it will be simply replaced by somaxconn as you can see in the code here.

Long time ago (before kernel 2.4.25) somaxconn value used to be hardcoded in the kernel, nowadays you can read and update using sysctl as with the rest of the network stack parameters. In most systems the default value is 128, like in my CentOS VM:

[root@server juan]# sysctl -a --pattern net.core.somaxconn
net.core.somaxconn = 128
[root@server juan]#

Test scenario

In order to test and confirm the behavior of somaxconn I have the following setup:

• Client VM (IP 192.168.0.17) running a C binary (source here) that will start 25 TCP connections to the Server VM on port 8080, in each connection it will send 4 bytes "juan". The binary opens 1 connection per second, and after having opened the 25 connections just waits for 2 minutes to finish.
• Server VM (IP 192.168.0.26) running ncat (nc, netcat, whatever you like to call it) listening on port 8080, and the maximum open files has been set to 9 (ulimit -n 9) to achieve a condition where we can see established connections being queued easier.

A few more details you should keep in mind:

• The version of nc shipped with CentOS sets a backlog of 10 on the listen() syscall (using strace):

[juan@server ~]$ ulimit -n 9
[juan@server ~]$ strace nc -lk 8080
execve("/usr/bin/nc", ["nc", "-lk", "8080"], [/* 24 vars */]) = 0
brk(0)                                  = 0x1dd7000
mmap(NULL, 4096, PROT_READ|PROT_WRITE, MAP_PRIVATE|MAP_ANONYMOUS, -1, 0) = 0x7fe7075e9000
...
bind(3, {sa_family=AF_INET6, sin6_port=htons(8080), inet_pton(AF_INET6, "::", &sin6_addr), sin6_flowinfo=0, sin6_scope_id=0}, 128) = 0
listen(3, 10)                           = 0
fcntl(3, F_GETFL)
...

• So we have a backlog of 10 set in the listen syscall and a limit of 9 open files. I will use this value as somaxconn since the meaning is the same.
• After nc was just started we can see it has already used 5 FD in use (STDIN, STDOUT, STDERR, and two more for the listening sockets on IPv4 and IPv6)

[root@server juan]# lsof -p 14136|grep "CHR\|IPv"
nc      14136 juan    0u   CHR     136,0      0t0        3 /dev/pts/0
nc      14136 juan    1u   CHR     136,0      0t0        3 /dev/pts/0
nc      14136 juan    2u   CHR     136,0      0t0        3 /dev/pts/0
nc      14136 juan    3u  IPv6 488270957      0t0      TCP *:webcache (LISTEN)
nc      14136 juan    4u  IPv4 488270958      0t0      TCP *:webcache (LISTEN)
[root@server juan]#

With all these details in mind and some basic math (2+2=4 :D) we can expect the following behavior:

• Since 5 out of the 9 available file descriptors are already in use, nc should not be able to receive more than 4 new connections on port 8080. Each new connection will create a new socket that has to be accessible in user space through a file descriptor (have a look at accept() syscall), which can't be created if the max open files limit has been reached.
• The C binary will issue 25 connections:
• The first 4 will be answered just fine by nc and the 4 bytes will be read from the socket and printed to STDOUT.
• The next 10 connections will be indeed accepted by the Network layer of the Server VM, and even the 4 bytes will be received, however nc won't be able to accept the socket and read the 4 bytes. These are the established connections being queued!!!
•  The remaining 11 connections will look as ESTABLISHED from the client as they have completed the TCP handshake however the 4 bytes won't be ACKnowledged by Network Stack because the queue is full (somaxconn limit has been reached). From the server the connections won't even exist.

Binary execution:

juan@test:~/TCP_connections$ gcc -o tcp_connections tcp_connections.c
juan@test:~/TCP_connections$ ./tcp_connections
Socket opened FD=3, connection number 0
Socket opened FD=4, connection number 1
Socket opened FD=5, connection number 2
Socket opened FD=6, connection number 3
Socket opened FD=7, connection number 4
Socket opened FD=8, connection number 5
Socket opened FD=9, connection number 6
Socket opened FD=10, connection number 7
Socket opened FD=11, connection number 8
Socket opened FD=12, connection number 9
Socket opened FD=13, connection number 10
Socket opened FD=14, connection number 11
Socket opened FD=15, connection number 12
Socket opened FD=16, connection number 13
Socket opened FD=17, connection number 14
Socket opened FD=18, connection number 15
Socket opened FD=19, connection number 16
Socket opened FD=20, connection number 17
Socket opened FD=21, connection number 18
Socket opened FD=22, connection number 19
Socket opened FD=23, connection number 20
Socket opened FD=24, connection number 21
Socket opened FD=25, connection number 22
Socket opened FD=26, connection number 23
Socket opened FD=27, connection number 24
juan@test:~/TCP_connections$

Nc execution on the server

Note: I introduced the new line after the 4th connections just to split them from the rest:

[juan@server ~]$ nc -lvk -p 8080
Ncat: Version 6.40 ( http://nmap.org/ncat )
Ncat: Listening on :::8080
Ncat: Listening on 0.0.0.0:8080
Ncat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49026.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49027.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49028.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49029.
juan

Ncat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49030.
Ncat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49031.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49032.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49033.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49034.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49035.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49036.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49037.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49038.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49039.
juanNcat: Connection from 192.168.0.17.
Ncat: Connection from 192.168.0.17:49040.
juanjuan 

Results

To have a  look at what was happening during the test I measured 3 different locations:

1. TCP connections on the client using ss.
2. TCP connections on the server using ss.
3. Captured network traffic on the server using tcpdump.

These 3 locations provided enough information to understand what is going on and to even find something interesting :D.

TCP connections on the client:

I've chopped off a couple of lines for the sake of space and time.  The samples were taken every 2 seconds and only TCP connections to port 8080 were considered:

root@test:/home/juan# for i in {1..100}; do ss -ntpe|grep "State\|8080"; echo ---; sleep 2; done
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
---
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49027         192.168.0.26:8080   users:(("tcp_connections",3342,4)) uid:1000 ino:23350 sk:ffff8800b4914140
ESTAB      0      0              192.168.0.17:49028         192.168.0.26:8080   users:(("tcp_connections",3342,5)) uid:1000 ino:23368 sk:ffff8800b4910e80
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
---
...
---
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49031         192.168.0.26:8080   users:(("tcp_connections",3342,8)) uid:1000 ino:23408 sk:ffff8800b4911d00
ESTAB      0      0              192.168.0.17:49027         192.168.0.26:8080   users:(("tcp_connections",3342,4)) uid:1000 ino:23350 sk:ffff8800b4914140
ESTAB      0      0              192.168.0.17:49029         192.168.0.26:8080   users:(("tcp_connections",3342,6)) uid:1000 ino:23372 sk:ffff8800b4910740
ESTAB      0      0              192.168.0.17:49030         192.168.0.26:8080   users:(("tcp_connections",3342,7)) uid:1000 ino:23390 sk:ffff8800b49115c0
ESTAB      0      0              192.168.0.17:49028         192.168.0.26:8080   users:(("tcp_connections",3342,5)) uid:1000 ino:23368 sk:ffff8800b4910e80
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
ESTAB      0      0              192.168.0.17:49033         192.168.0.26:8080   users:(("tcp_connections",3342,10)) uid:1000 ino:23445 sk:ffff8800b4912b80
ESTAB      0      0              192.168.0.17:49034         192.168.0.26:8080   users:(("tcp_connections",3342,11)) uid:1000 ino:23447 sk:ffff8800b49132c0
ESTAB      0      0              192.168.0.17:49032         192.168.0.26:8080   users:(("tcp_connections",3342,9)) uid:1000 ino:23426 sk:ffff8800b4912440
---
...

After a few seconds, we can see a few ESTABLISHED tcp connections using source ports from 49026 to 49034, 9 connections to be more precise, and they all show 0 bytes in Send-Q which suggests the 4 bytes sent by the application were actually acknowledged by the server.

...
---
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49031         192.168.0.26:8080   users:(("tcp_connections",3342,8)) uid:1000 ino:23408 sk:ffff8800b4911d00
ESTAB      0      0              192.168.0.17:49027         192.168.0.26:8080   users:(("tcp_connections",3342,4)) uid:1000 ino:23350 sk:ffff8800b4914140
ESTAB      0      0              192.168.0.17:49029         192.168.0.26:8080   users:(("tcp_connections",3342,6)) uid:1000 ino:23372 sk:ffff8800b4910740
ESTAB      0      0              192.168.0.17:49030         192.168.0.26:8080   users:(("tcp_connections",3342,7)) uid:1000 ino:23390 sk:ffff8800b49115c0
ESTAB      0      0              192.168.0.17:49028         192.168.0.26:8080   users:(("tcp_connections",3342,5)) uid:1000 ino:23368 sk:ffff8800b4910e80
ESTAB      0      0              192.168.0.17:49037         192.168.0.26:8080   users:(("tcp_connections",3342,14)) uid:1000 ino:23502 sk:ffff8800b4917400
ESTAB      0      0              192.168.0.17:49035         192.168.0.26:8080   users:(("tcp_connections",3342,12)) uid:1000 ino:23465 sk:ffff8800b4913a00
ESTAB      0      0              192.168.0.17:49036         192.168.0.26:8080   users:(("tcp_connections",3342,13)) uid:1000 ino:23484 sk:ffff8800b4915e40
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
ESTAB      0      0              192.168.0.17:49038         192.168.0.26:8080   users:(("tcp_connections",3342,15)) uid:1000 ino:23520 sk:ffff8800b4916580
ESTAB      0      0              192.168.0.17:49033         192.168.0.26:8080   users:(("tcp_connections",3342,10)) uid:1000 ino:23445 sk:ffff8800b4912b80
ESTAB      0      0              192.168.0.17:49034         192.168.0.26:8080   users:(("tcp_connections",3342,11)) uid:1000 ino:23447 sk:ffff8800b49132c0
ESTAB      0      0              192.168.0.17:49040         192.168.0.26:8080   users:(("tcp_connections",3342,17)) uid:1000 ino:23557 sk:ffff8800b4914880
ESTAB      0      0              192.168.0.17:49039         192.168.0.26:8080   users:(("tcp_connections",3342,16)) uid:1000 ino:23539 sk:ffff8800b4915700
ESTAB      0      0              192.168.0.17:49032         192.168.0.26:8080   users:(("tcp_connections",3342,9)) uid:1000 ino:23426 sk:ffff8800b4912440
---
...

A few more seconds later we see even more TCP connections in ESTABLISHED state, including src ports from 49035 to 49040. So we have a total of 15 ESTABLISHED connections with 0 bytes waiting to be ACKnowledged by the server. Remember we were expecting 14 (4 + 10), but instead we got 15 (4 + 11), odd right? I'll get back to this later...

...
---
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49031         192.168.0.26:8080   users:(("tcp_connections",3342,8)) uid:1000 ino:23408 sk:ffff8800b4911d00
ESTAB      0      0              192.168.0.17:49027         192.168.0.26:8080   users:(("tcp_connections",3342,4)) uid:1000 ino:23350 sk:ffff8800b4914140
ESTAB      0      0              192.168.0.17:49029         192.168.0.26:8080   users:(("tcp_connections",3342,6)) uid:1000 ino:23372 sk:ffff8800b4910740
ESTAB      0      0              192.168.0.17:49030         192.168.0.26:8080   users:(("tcp_connections",3342,7)) uid:1000 ino:23390 sk:ffff8800b49115c0
ESTAB      0      0              192.168.0.17:49028         192.168.0.26:8080   users:(("tcp_connections",3342,5)) uid:1000 ino:23368 sk:ffff8800b4910e80
ESTAB      0      0              192.168.0.17:49037         192.168.0.26:8080   users:(("tcp_connections",3342,14)) uid:1000 ino:23502 sk:ffff8800b4917400
ESTAB      0      0              192.168.0.17:49035         192.168.0.26:8080   users:(("tcp_connections",3342,12)) uid:1000 ino:23465 sk:ffff8800b4913a00
ESTAB      0      0              192.168.0.17:49036         192.168.0.26:8080   users:(("tcp_connections",3342,13)) uid:1000 ino:23484 sk:ffff8800b4915e40
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
ESTAB      0      0              192.168.0.17:49038         192.168.0.26:8080   users:(("tcp_connections",3342,15)) uid:1000 ino:23520 sk:ffff8800b4916580
ESTAB      0      0              192.168.0.17:49033         192.168.0.26:8080   users:(("tcp_connections",3342,10)) uid:1000 ino:23445 sk:ffff8800b4912b80
ESTAB      0      0              192.168.0.17:49034         192.168.0.26:8080   users:(("tcp_connections",3342,11)) uid:1000 ino:23447 sk:ffff8800b49132c0
ESTAB      0      0              192.168.0.17:49040         192.168.0.26:8080   users:(("tcp_connections",3342,17)) uid:1000 ino:23557 sk:ffff8800b4914880
ESTAB      0      4              192.168.0.17:49041         192.168.0.26:8080   timer:(on,1.208ms,3) users:(("tcp_connections",3342,18)) uid:1000 ino:23575 sk:ffff8800b4916cc0
ESTAB      0      0              192.168.0.17:49039         192.168.0.26:8080   users:(("tcp_connections",3342,16)) uid:1000 ino:23539 sk:ffff8800b4915700
ESTAB      0      0              192.168.0.17:49032         192.168.0.26:8080   users:(("tcp_connections",3342,9)) uid:1000 ino:23426 sk:ffff8800b4912440
ESTAB      0      4              192.168.0.17:49042         192.168.0.26:8080   timer:(on,608ms,2) users:(("tcp_connections",3342,19)) uid:1000 ino:23593 sk:ffff8800b4910000
---
...

This new sample shows 2 lines that are different than the rest, the ones using src ports 49041 and 49042.  These were the first 2 connections that couldn't fit in the somaxconn queue!!! And even more, you can see how the 4 bytes that were sent from the client haven't been acknowledged by the server and therefore they show up in the Send-Q column. Note how the connection looks as ESTABLISHED for the client though, this is because the 3-way handshake was completed from the client point of view.

...
---
State      Recv-Q Send-Q        Local Address:Port          Peer Address:Port
ESTAB      0      0              192.168.0.17:49031         192.168.0.26:8080   users:(("tcp_connections",3342,8)) uid:1000 ino:23408 sk:ffff8800b4911d00
ESTAB      0      0              192.168.0.17:49027         192.168.0.26:8080   users:(("tcp_connections",3342,4)) uid:1000 ino:23350 sk:ffff8800b4914140
ESTAB      0      0              192.168.0.17:49029         192.168.0.26:8080   users:(("tcp_connections",3342,6)) uid:1000 ino:23372 sk:ffff8800b4910740
ESTAB      0      4              192.168.0.17:49047         192.168.0.26:8080   timer:(on,460ms,4) users:(("tcp_connections",3342,24)) uid:1000 ino:23632 sk:ffff8800a6efba00
ESTAB      0      4              192.168.0.17:49050         192.168.0.26:8080   timer:(on,132ms,3) users:(("tcp_connections",3342,27)) uid:1000 ino:23635 sk:ffff8800a6efc140
ESTAB      0      0              192.168.0.17:49030         192.168.0.26:8080   users:(("tcp_connections",3342,7)) uid:1000 ino:23390 sk:ffff8800b49115c0
ESTAB      0      0              192.168.0.17:49028         192.168.0.26:8080   users:(("tcp_connections",3342,5)) uid:1000 ino:23368 sk:ffff8800b4910e80
ESTAB      0      4              192.168.0.17:49045         192.168.0.26:8080   timer:(on,4.740ms,5) users:(("tcp_connections",3342,22)) uid:1000 ino:23630 sk:ffff8800a6efcfc0
ESTAB      0      4              192.168.0.17:49049         192.168.0.26:8080   timer:(on,2.336ms,4) users:(("tcp_connections",3342,26)) uid:1000 ino:23634 sk:ffff8800a6efc880
ESTAB      0      0              192.168.0.17:49037         192.168.0.26:8080   users:(("tcp_connections",3342,14)) uid:1000 ino:23502 sk:ffff8800b4917400
ESTAB      0      0              192.168.0.17:49035         192.168.0.26:8080   users:(("tcp_connections",3342,12)) uid:1000 ino:23465 sk:ffff8800b4913a00
ESTAB      0      4              192.168.0.17:49043         192.168.0.26:8080   timer:(on,2.740ms,5) users:(("tcp_connections",3342,20)) uid:1000 ino:23611 sk:ffff8800a6efde40
ESTAB      0      0              192.168.0.17:49036         192.168.0.26:8080   users:(("tcp_connections",3342,13)) uid:1000 ino:23484 sk:ffff8800b4915e40
ESTAB      0      4              192.168.0.17:49044         192.168.0.26:8080   timer:(on,3.732ms,5) users:(("tcp_connections",3342,21)) uid:1000 ino:23616 sk:ffff8800a6efd700
ESTAB      0      4              192.168.0.17:49046         192.168.0.26:8080   timer:(on,5.740ms,5) users:(("tcp_connections",3342,23)) uid:1000 ino:23631 sk:ffff8800a6eff400
ESTAB      0      0              192.168.0.17:49026         192.168.0.26:8080   users:(("tcp_connections",3342,3)) uid:1000 ino:23326 sk:ffff8800b4914fc0
ESTAB      0      4              192.168.0.17:49048         192.168.0.26:8080   timer:(on,1.336ms,4) users:(("tcp_connections",3342,25)) uid:1000 ino:23633 sk:ffff8800a6efecc0
ESTAB      0      0              192.168.0.17:49038         192.168.0.26:8080   users:(("tcp_connections",3342,15)) uid:1000 ino:23520 sk:ffff8800b4916580
ESTAB      0      0              192.168.0.17:49033         192.168.0.26:8080   users:(("tcp_connections",3342,10)) uid:1000 ino:23445 sk:ffff8800b4912b80
ESTAB      0      0              192.168.0.17:49034         192.168.0.26:8080   users:(("tcp_connections",3342,11)) uid:1000 ino:23447 sk:ffff8800b49132c0
ESTAB      0      0              192.168.0.17:49040         192.168.0.26:8080   users:(("tcp_connections",3342,17)) uid:1000 ino:23557 sk:ffff8800b4914880
ESTAB      0      4              192.168.0.17:49041         192.168.0.26:8080   timer:(on,732ms,5) users:(("tcp_connections",3342,18)) uid:1000 ino:23575 sk:ffff8800b4916cc0
ESTAB      0      0              192.168.0.17:49039         192.168.0.26:8080   users:(("tcp_connections",3342,16)) uid:1000 ino:23539 sk:ffff8800b4915700
ESTAB      0      0              192.168.0.17:49032         192.168.0.26:8080   users:(("tcp_connections",3342,9)) uid:1000 ino:23426 sk:ffff8800b4912440
ESTAB      0      4              192.168.0.17:49042         192.168.0.26:8080   timer:(on,1.732ms,5) users:(("tcp_connections",3342,19)) uid:1000 ino:23593 sk:ffff8800b4910000
---
^C
root@test:/home/juan#

The last sample shows the remaining connections from ports 49043 to 49050 all of them in the same condition, 4 bytes not being acknowledged.

From the client side samples we can confirm we got 15 complete TCP connections (src ports from 49026 to 49040) and 10 that even though showed up as ESTABLISHED weren't able to get acknowledged the 4 bytes sent by the client (src ports from 49041 to 49050).

TCP connections on the server

Lets have a look now to the samples taken on the server and see if they match with what we found on the client.

[root@server juan]# for i in {1..100}; do ss -tpn|grep "State\|8080"; echo "---"; sleep 2;done
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49026               users:(("nc",pid=13705,fd=5))
---
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49026               users:(("nc",pid=13705,fd=5))
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49028               users:(("nc",pid=13705,fd=7))
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49027               users:(("nc",pid=13705,fd=6))
---
...

The first samples look ok, nothing fancy there, we can see the first 3 TCP connections using src ports from 49026 to 49028.

...
---
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49026               users:(("nc",pid=13705,fd=5))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49031
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49033
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49029               users:(("nc",pid=13705,fd=8))
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49028               users:(("nc",pid=13705,fd=7))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49032
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49030
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49027               users:(("nc",pid=13705,fd=6))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49034
---
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49036
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49026               users:(("nc",pid=13705,fd=5))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49035
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49031
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49033
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49029               users:(("nc",pid=13705,fd=8))
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49028               users:(("nc",pid=13705,fd=7))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49032
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49030
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49027               users:(("nc",pid=13705,fd=6))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49034
---
...

And here it got interesting! We have now 4 connections (src ports between 49026 and 49029) which besides being ESTABLISHED have a FD associated to our nc process. However we have another 7 ESTABLISHED connections (src ports from 49030 to 49036) with no FD associated (and no process either :D)!!! These 7 connections are the ones waiting on the queue for nc to issue the accept() call. nc is actually issuing the accept calls, but the calls are failing due to nc having reached the maximum open files (because of the "ulimit -n 9").
 

...
---
State      Recv-Q Send-Q Local Address:Port               Peer Address:Port
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49036
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49026               users:(("nc",pid=13705,fd=5))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49038
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49035
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49031
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49033
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49029               users:(("nc",pid=13705,fd=8))
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49028               users:(("nc",pid=13705,fd=7))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49032
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49039
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49030
ESTAB      0      0      192.168.0.26:8080               192.168.0.17:49027               users:(("nc",pid=13705,fd=6))
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49037
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49040
ESTAB      4      0      192.168.0.26:8080               192.168.0.17:49034
---
^C
[root@server juan]#

After the binary issued the 25 connections, on the server we can see 4 ESTABLISHED connections (src ports 49026 to 49029) with corresponding FDs and 11 ESTABLISHED connections (src ports 49030 to 49040) with no FD. So... where are the remaining 10 connections that show up as ESTABLISHED on the client??? Well, these 10 connections didn't reach ESTABLISHED state on the server :D as per the documentation of listen():

The backlog argument defines the maximum length to which the queue of pending connections for sockfd may grow.  If a connection request arrives when the queue is full, the client may receive an error with an indication of ECONNREFUSED or, if the underlying protocol supports retransmission, the request may be ignored so that a later reattempt at connection succeeds.

Considering we are using TCP , the use case matches exactly with the underlined part.

To be continued...

Death by Real Time scheduling

A few weeks ago I had the chance to troubleshoot a system that was literally crawling performance wise. A simple SSH connection would take a few seconds to be established and then the latency on the session would be really frustrating. Clearly something was putting the system on its knees. A simple look at the logs threw the first clue:

[18253.961495] sched: RT throttling activated

These simple 4 words were enough to put me on the right track and I asked, "Do you happen to have any processes using a Real Time scheduling policy?"...

Linux Scheduler

There's a "bit" of code in the kernel that decides which process will get to be executed next and that code is called Scheduler. In short, the scheduler is in charge of assigning CPU time to processes according to certain parameters. In Linux threads are scheduled considering two factors (ok, 2 + 1 if you want :P):

• The scheduling policy: there are basically two different types of scheduling policies, regular policies (SCHED_OTHER aka SCHED_NORMAL, SCHED_BATCH, SCHED_IDLE) and real time policies (SCHED_FIFO, SCHED_RR, SCHED_DEADLINE). The regular policies are implemented using the Completely Fair Scheduler (CFS):
• SCHED_NORMAL: regular scheduling policy, nothing fancy here, tasks get to be executed for a period of time and preemption is in place as well.
• SCHED_BATCH: allows tasks to run longer periods of time before preempting them, this improves for example the use of cache lines (but of course reducing interactivity).
• SCHED_IDLE: tasks with this policy have less priority than nice 19.
• SCHED_FIFO: is a simple scheduling algorithm without time slicing, based in a set of queues for the available priorities. Static priority must be higher than 0.
• SCHED_RR: unlike in SCHED_FIFO policy, threads under SCHED_RR run for a certain time slice called quantum and if they reach that time slice they are put at the end of its priority queue.
• SCHED_DEADLINE: uses three parameters, named "runtime", "period", and "deadline", to schedule tasks. A SCHED_DEADLINE task should receive "runtime" microseconds of execution time every "period" microseconds, and these "runtime" microseconds are available within "deadline" microseconds from the beginning of the period.
• Static priority: also known as sched_priority is a value between 1 and 99. This value only affects Real Time scheduling policies, it has no effect on regular policies and in fact should be set to 0.

In a brief:

       Conceptually, the scheduler maintains a list of runnable threads for
       each possible sched_priority value.  In order to determine which
       thread runs next, the scheduler looks for the nonempty list with the
       highest static priority and selects the thread at the head of this
       list.

There's another concept to mention when it comes to scheduling and is the "niceness" (this is the +1). This value, which only affects SCHED_OTHER and SCHED_BATCH policies, is used to influence the scheduler behavior to favor or disfavor certain threads. Linux's CFS (Completely Fair Scheduler) will then use the nice value to schedule the processes accordingly. Nice can take any integer value between [-20,19], being -20 the highest priority and 19 the lowest. This is the value you can change using nice command from your shell.

How do you find the Scheduling Policy of a process?

The easiest way to get the scheduling information from a process is by using our well known ps command. We can have a look at the process of the system like in the following example:

juan@test:~$ ps -eo pid,user,class,pri,nice,rtprio|awk '{print $3,$5,$6}'|sort|uniq -c
      1 CLS NI RTPRIO
      4 FF - 99
    106 TS 0 -
      1 TS 1 -
      1 TS -10 -
      1 TS 19 -
     31 TS -20 -
      1 TS 5 -
juan@test:~$

there we can see:

• 4 processes running with real time policy FF (SCHED_FIFO) with real time priority 99. Also note how the NI (nice) column is null for these processes as we described before.
• 141 processes with regular policy TS (SCHED_OTHER, you can see this in "man ps"). Also note how the RTPRIO (real time priority) column is null for these processes as we described before.

If we have a closer look at the real time threads (FF) we can see that they are kernel threads (one per available core):

juan@test:~$ ps -eo pid,cmd,user,pcpu,class,pri,nice,rtprio|grep "FF\|PID"|grep -v grep
  PID CMD                         USER     %CPU CLS PRI  NI RTPRIO
   11 [migration/0]               root      0.0 FF  139   -     99
   12 [watchdog/0]                root      0.0 FF  139   -     99
   13 [watchdog/1]                root      0.0 FF  139   -     99
   14 [migration/1]               root      0.0 FF  139   -     99
juan@test:~$

• watchdog threads are there in order to identify software lockups conditions 
• migration threads are there to handle load balance tasks among the available cores

These threads use a real time policy because their execution on time is crucial for the health of the system, however they only run for really short periods of time and that's the reason why they don't cause any pain.

Real time Policy

The core of the this post was actually real time policy right? Well lets have a look at the particularities of this policy and why it could become a headache easily.

• SCHED_FIFO policy doesn't use time slicing (SCHED_RR does though)
• So a SCHED_FIFO task will run until:
• A higher priority task goes in runable state and gets scheduled right away.
• It blocks due to IO
• Executes sched_yield call. 

With these details said, you should already get an idea of how an out of control RT task could become a big problem.

CPU Starvation

The problem a RT task can cause is called CPU starvation. The idea of the starvation situation is that there's a small number of tasks (even just one) consuming most or all of certain resource in this case the CPU time. Here you can see a simple example of a real time process that goes into an infinite loop causing CPU starvation to the rest (scheduling policy is set to SCHED_FIFO in line 23).

Code (remember you can pull this example or the others from https://github.com/jjpavlik):

#include <stdio.h>
#include <sched.h>
#include <errno.h>
#include <string.h>
#include <sys/time.h>
#include <sys/resource.h>

void main()
{
        int sched,pri,pid,min,max,i,aux,error;
        struct sched_param params;

        pid = getpid();

        sched = sched_getscheduler(pid);
        pri = getpriority(PRIO_PROCESS,0);
        printf("PID=%d\n",pid);
        printf("Current scheduler is %d, current priority is %d\n",sched,pri);
        printf("Priorities MIN=%d, MAX=%d, nice=%d\n",sched_get_priority_min(sched), sched_get_priority_max(sched),getpriority(PRIO_PROCESS,0));

        printf("Changing scheduling class to SCHED_FIFO\n");
        params.sched_priority=99;
        aux = sched_setscheduler(pid,SCHED_FIFO,&params);
        error=errno;
        if( aux == -1)
        {
                //You need to run this as root :D, otherwise you will get a permission denied
                printf("Setscheduler failed: %s\n",strerror(error));
                return;
        }
        sched = sched_getscheduler(pid);
        pri = getpriority(PRIO_PROCESS,0);
        printf("Scheduler is %d, current priority is %d\n",sched,pri);
        printf("Priorities MIN=%d, MAX=%d, nice=%d\n",sched_get_priority_min(sched), sched_get_priority_max(sched),getpriority(PRIO_PROCESS,0));

        while(1)
        {//Inifinite loop
                i++;
        }
}

Execution:

root@test:/home/juan/scheduling_tests# ./sched_details &
[1] 3265
PID=3265
Current scheduler is 0, current priority is 0
Priorities MIN=0, MAX=0, nice=0
Changing scheduling class to SCHED_FIFO
Scheduler is 1, current priority is 0
Priorities MIN=1, MAX=99, nice=0
root@test:/home/juan/scheduling_tests# 
root@test:/home/juan/scheduling_tests# ps -eo pid,cmd,user,pcpu,class,pri,nice,rtprio|grep "FF\|PID"|grep -v grep
  PID CMD                         USER     %CPU CLS PRI  NI RTPRIO 
   11 [migration/0]               root      0.0 FF  139   -     99
   12 [watchdog/0]                root      0.0 FF  139   -     99
   13 [watchdog/1]                root      0.0 FF  139   -     99
   14 [migration/1]               root      0.0 FF  139   -     99
 3265./sched_details             root     99.3 FF  139   -     99
root@test:/home/juan/scheduling_tests#

Clearly the process is consuming almost completely one of the available cores in my system (99.3%), however we still don't see the throttling message on the logs because there's a second core available. So to push this even further I started a second run of the same binary to make sure the other core gets hammered as well and now:

root@test:/home/juan/scheduling_tests# ps -eo pid,cmd,user,pcpu,class,pri,nice,rtprio|grep "FF\|PID"|grep -v grep
  PID CMD                         USER     %CPU CLS PRI  NI RTPRIO 
   11 [migration/0]               root      0.0 FF  139   -     99
   12 [watchdog/0]                root      0.0 FF  139   -     99
   13 [watchdog/1]                root      0.0 FF  139   -     99
   14 [migration/1]               root      0.0 FF  139   -     99
 3299 ./sched_details             root     97.9 FF  139   -     99
 3338 ./sched_details             root     95.8 FF  139   -     99
root@test:/home/juan/scheduling_tests#

After a few seconds you should see the throttling activated message on your logs:

root@test:/home/juan/scheduling_tests# dmesg |tail -1
[ 9640.055754] sched: RT throttling activated
root@test:/home/juan/scheduling_tests#

at this stage the system is indeed crawling and barely responding to every command. But what does "sched: RT throttling activated" means after all?

There are two kernel parameters that help us reduce the impact of this situation with real time processes. Here you can see them:

root@test:/home/juan/scheduling_tests# cat /proc/sys/kernel/sched_rt_period_us
1000000
root@test:/home/juan/scheduling_tests# cat /proc/sys/kernel/sched_rt_runtime_us
950000
root@test:/home/juan/scheduling_tests#

• sched_rt_period_us specifies a scheduling period that is equivalent to 100% CPU bandwidth.
• sched_rt_runtime_us specifies how much of the rt_period can be used by real time and deadline tasks.

In my setup (default Ubuntu setup) the RT period is 1000000 us (1 second) and the RT runtime is 950000 us, meaning that 95% of the time can be used by realtime tasks, leaving 5% to other scheduling policies. This 5% of CPU time should be enough (being patience) to login to the system and get rid of the rogue processes, unless you have many other processes running as well.

For example, changing 950000 to 500000 would allow RT tasks to use up to around 50% of the CPU time:

root@test:/home/juan/scheduling_tests# echo 500000 > /proc/sys/kernel/sched_rt_runtime_us
root@test:/home/juan/scheduling_tests# cat /proc/sys/kernel/sched_rt_runtime_us
500000
root@test:/home/juan/scheduling_tests#
root@test:/home/juan/scheduling_tests# ps -eo pid,cmd,user,pcpu,class,pri,nice,rtprio|grep "FF\|PID"|grep -v grep
  PID CMD                         USER     %CPU CLS PRI  NI RTPRIO
   11 [migration/0]               root      0.0 FF  139   -     99
   12 [watchdog/0]                root      0.0 FF  139   -     99
   13 [watchdog/1]                root      0.0 FF  139   -     99
   14 [migration/1]               root      0.0 FF  139   -     99
 3394 ./sched_details             root     58.7 FF  139   -     99
 3395 ./sched_details             root     50.0 FF  139   -     99
root@test:/home/juan/scheduling_tests#

so this way you can keep the real time processes under control.

However, considering real time tasks are supposed to be time sensitive you should avoid capping them like this unless it was really necessary. Maybe it's worth having a look at why they are consuming so much CPU time instead, usually real time tasks are operations that take really short periods of time but they need to be executed as soon as possible. So tools like strace or even perf should be really good starting points to identify the reason behind the CPU time, even better if you have access to the source code!