Mostrando entradas con la etiqueta ubuntu. Mostrar todas las entradas
Mostrando entradas con la etiqueta ubuntu. Mostrar todas las entradas

lunes, 30 de abril de 2018

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!

jueves, 21 de diciembre de 2017

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.

lunes, 15 de mayo de 2017

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).

sábado, 6 de mayo de 2017

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:
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...

martes, 28 de marzo de 2017

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!

jueves, 17 de noviembre de 2016

Where did my disk space go??? Is df lying to me? or is it du lying?

I had an interesting situation today and thought might be a good idea to share it here. Basically the problem was more or less the following:
  1. A critical production system was running out of disk space and things were going downhills scarcely fast, df was showing utilization at 99% already.
  2. The user decided to delete some big log files in order to free up some space.
  3. After that df was still showing 99% , however running du on the root directory would show less space being utilized.
You can imagine now how unhappy the user was when realized that deleting files was not freeing any disk space and he was about to see the system become totally useless. On top of that he couldn't explain why df and du wouldn't come into an agreement in terms of free space on the system.

What was happening here? Was df or du lying to the user?


Well... software in general doesn't lie, usually what actually happens is that we don't really understand how it works and therefore we expect a different behavior. The root cause of the problem mentioned before is the unlink syscall, why? we can get the answer by asking the oracle (man 2 unlink):
DESCRIPTION
       unlink() deletes a name from the filesystem.  If that name was the last
       link to a file and no processes have the file open, the file is deleted
       and the space it was using is made available for reuse.

       If  the  name  was the last link to a file but any processes still have
       the file open, the file will remain in existence until  the  last  file
       descriptor referring to it is closed.

       ...
Yes :D, turns out that if you delete a file and there's at least one process that has a file descriptor pointing to that file, the space of the file won't be available right away.

Lets reproduce this:


The easiest way to understand this is by actually reproducing the behavior. I just used dd to fill-up the drive and the result was this:
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.7G     0 100% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.7G    /
7.7G    total
[ec2-user@ip-172-31-16-117 ~]$ echo a > file
-bash: echo: write error: No space left on device
[ec2-user@ip-172-31-16-117 ~]$
the system has clearly ran out of disk space at this point and we can't even add a single byte to a file. Now the next step would be to free up some space, so we check with du where we can find some files to delete:
[ec2-user@ip-172-31-16-117 ~]$ du -sch /* 2>/dev/null
7.0M    /bin
25M     /boot
4.0K    /cgroup
56K     /dev
9.1M    /etc
6.7G    /home
46M     /lib
23M     /lib64
4.0K    /local
16K     /lost+found
4.0K    /media
4.0K    /mnt
43M     /opt
0       /proc
4.0K    /root
8.0K    /run
12M     /sbin
4.0K    /selinux
4.0K    /srv
0       /sys
8.0K    /tmp
802M    /usr
48M     /var
7.7G    total
[ec2-user@ip-172-31-16-117 ~]$
the size of /home is a bit crazy considering the size of the partition itself so lets delete some files from /home/ec2-user:
[ec2-user@ip-172-31-16-117 ~]$ ls -lah
total 6.7G
drwx------ 3 ec2-user ec2-user 4.0K Nov 17 20:10 .
drwxr-xr-x 3 root     root     4.0K Nov 17 18:42 ..
-rw-r--r-- 1 ec2-user ec2-user   18 Aug 15 23:52 .bash_logout
-rw-r--r-- 1 ec2-user ec2-user  193 Aug 15 23:52 .bash_profile
-rw-r--r-- 1 ec2-user ec2-user  124 Aug 15 23:52 .bashrc
-rw-rw-r-- 1 ec2-user ec2-user 306M Nov 17 20:09 big_file
-rw-rw-r-- 1 ec2-user ec2-user    0 Nov 17 20:10 file
-rw-rw-r-- 1 ec2-user ec2-user 6.4G Nov 17 18:44 fillingup
-rwxrwxr-x 1 ec2-user ec2-user 7.0K Nov 17 20:09 service
-rw-rw-r-- 1 ec2-user ec2-user  309 Nov 17 20:09 service.c
drwx------ 2 ec2-user ec2-user 4.0K Nov 17 18:42 .ssh
-rw------- 1 ec2-user ec2-user 2.1K Nov 17 20:09 .viminfo
[ec2-user@ip-172-31-16-117 ~]$ rm big_file
[ec2-user@ip-172-31-16-117 ~]$
[ec2-user@ip-172-31-16-117 ~]$ echo a > file
-bash: echo: write error: No space left on device
[ec2-user@ip-172-31-16-117 ~]$
I've just deleted a 306Mbytes file and can't even write 1 single byte!!! Having a look at df and du things look like:
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.7G     0 100% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.4G    /
7.4G    total
[ec2-user@ip-172-31-16-117 ~]$
while du shows the expected size, df insists in saying the partition is at 100% utilization. Cool, with just a few steps we have reproduced the situation!

The reason behind the difference between df and du is in the fact that du calculates the size of the folders by adding up the size of the files inside and big_file does not exist anymore on the folder (has been removed from the directory entry), while df shows the real available space of the file system.

With all this in mind, the only reason why the file system size wouldn't change after deleting a file is because there's at least one process that keeps a file descriptor pointing to the deleted file (you can read more about open files and file descriptors in Linux limits 102 - Open Files). We can easily identify the process that holds the file descriptor by simple using our lovely lsof:
[ec2-user@ip-172-31-16-117 ~]$ lsof |grep "\(deleted\)"
service   23177 ec2-user    3r      REG  202,1 319934464  14708 /home/ec2-user/big_file (deleted)
[ec2-user@ip-172-31-16-117 ~]$
ja! turns out process "service" with PID 23177 has a file descriptor that points to file /home/ec2-user/big_file and that file has been deleted!!! So if we get rid of process service then the space should be finally available, lets confirm that:
[ec2-user@ip-172-31-16-117 ~]$ kill -9 23177
[ec2-user@ip-172-31-16-117 ~]$ 
[1]+  Killed                  ./service
[ec2-user@ip-172-31-16-117 ~]$ df -h
Filesystem      Size  Used Avail Use% Mounted on
devtmpfs        3.9G   56K  3.9G   1% /dev
tmpfs           3.9G     0  3.9G   0% /dev/shm
/dev/xvda1      7.8G  7.4G  306M  97% /
[ec2-user@ip-172-31-16-117 ~]$ du -sch / 2>/dev/null
7.4G    /
7.4G    total
[ec2-user@ip-172-31-16-117 ~]$
and magic happened!!! When the processes was terminated the fd was finally closed and the last reference to the file disappeared causing the space to bee available now and therefore df matches with du now.

Depending on which process is keeping the file open you may have other options besides killing it, for example:
  • Restarting it if it's a service.
  • Perhaps sending another signal (for example to rotate logs?). 
  • If for some reason (uninterruptible state) you can't kill the process then the only easy way here is to restart the whole system.

domingo, 16 de octubre de 2016

Linux limits 102 - Open files

This post is kind of a follow up of Linux limits 101 - Ulimit from a few weeks ago where we went through ulimit and how they are used to limit users behaviors. This time we'll take a look at another limit the kernel can impose on us and therefore make our lives a bit sower, the number of open files.

I think it's worth mentioning (I may have said this before xD) that when we talk about Open Files in Linux systems we are basically talking about File descriptors (aka file handles). A file descriptor is a data structure used by processes to access: files, Unix sockets, Networking sockets, pipes, etc. Every new process comes by default with 3 file descriptors:
  • FD 0: standard input
  • FD 1: standard output
  • FD 2: standard error
So just by having lets say:
juan@test:~$ ps aux|wc -l
142
juan@test:~$
about 142 processes running on the system, we should expect at least around 426 file descriptors to be in use (142x3=426). What if there was a way to know how many file descriptors a particular process is using?

File descriptors a process is using:


Yeahp, of course that's possible! And as always in Linux, there are at least two different ways. The first approach will be of course the easiest one, each process has a folder under /proc that will provide loads of information, in this case will focus on subfolder fd, where guess what's going to show up? indeed, the file descriptors for the process:
root@test:/home/juan# ls /proc/1/fd | wc -l
24
root@test:/home/juan#
init process (PID=1) has 24 file descriptors in use! We can see more details about them in the next output:
root@test:/home/juan# ls -la /proc/1/fd
total 0
dr-x------ 2 root root  0 Oct 15 10:39 .
dr-xr-xr-x 9 root root  0 Oct 15 10:38 ..
lrwx------ 1 root root 64 Oct 15 10:39 0 -> /dev/null
lrwx------ 1 root root 64 Oct 15 10:39 1 -> /dev/null
lrwx------ 1 root root 64 Oct 15 10:39 10 -> socket:[8662]
lrwx------ 1 root root 64 Oct 15 10:39 11 -> socket:[9485]
l-wx------ 1 root root 64 Oct 15 10:39 12 -> /var/log/upstart/network-manager.log.1 (deleted)
lrwx------ 1 root root 64 Oct 15 10:39 14 -> socket:[10329]
l-wx------ 1 root root 64 Oct 15 10:39 16 -> /var/log/upstart/systemd-logind.log.1 (deleted)
lrwx------ 1 root root 64 Oct 15 10:39 17 -> socket:[8637]
lrwx------ 1 root root 64 Oct 15 10:39 18 -> /dev/ptmx
lrwx------ 1 root root 64 Oct 15 10:39 2 -> /dev/null
lrwx------ 1 root root 64 Oct 15 10:39 20 -> /dev/ptmx
lrwx------ 1 root root 64 Oct 15 10:39 22 -> /dev/ptmx
l-wx------ 1 root root 64 Oct 15 10:39 24 -> /var/log/upstart/modemmanager.log.1 (deleted)
lrwx------ 1 root root 64 Oct 15 10:39 29 -> /dev/ptmx
lr-x------ 1 root root 64 Oct 15 10:39 3 -> pipe:[8403]
lrwx------ 1 root root 64 Oct 15 10:39 30 -> /dev/ptmx
l-wx------ 1 root root 64 Oct 15 10:39 31 -> /var/log/upstart/mysql.log.1 (deleted)
lrwx------ 1 root root 64 Oct 15 10:39 34 -> /dev/ptmx
lrwx------ 1 root root 64 Oct 15 10:39 36 -> /dev/ptmx
l-wx------ 1 root root 64 Oct 15 10:39 4 -> pipe:[8403]
lr-x------ 1 root root 64 Oct 15 10:39 5 -> anon_inode:inotify
lr-x------ 1 root root 64 Oct 15 10:39 6 -> anon_inode:inotify
lrwx------ 1 root root 64 Oct 15 10:39 7 -> socket:[8404]
lrwx------ 1 root root 64 Oct 15 10:39 9 -> socket:[12675]
root@test:/home/juan#
we can see how the file descriptors are represented as links, a brief of the output would be:
  • Default file descriptors (0,1 and 2) have been pointed to /dev/null, which is ok for a process like init that isn't an interactive process.
  • There are a couple of UNIX sockets "socket:[XXXX]" opened (7,9,10, 11, etc), probably to connect to other processes.
  • There's a pipe "pipe:[8403]" as well using two fd (3 and 4) that's normal, pipes provide a fd to write and one to read while data is buffered on the kernel.
  • The rest of the fs point to:
    • /dev/ptmx pseudo terminal device.
    • inotify a way to monitor changes on files, this means init is interested in the events on two particular fd.
    • some deleted log files like /var/log/upstart/mysql.log.1 this is odd. Probably files were rotated or something like that.
 If for some reason these details weren't enough, you can go hardcore and try the second way.  lsof (list open files, makes sense, right?) is the program you need for that.

Lets list all the open files for a particular process using lsof, init in this case:
root@test:/home/juan# lsof -p 1
lsof: WARNING: can't stat() fuse.gvfsd-fuse file system /run/user/112/gvfs
      Output information may be incomplete.
COMMAND PID USER   FD   TYPE             DEVICE SIZE/OFF   NODE NAME
init      1 root  cwd    DIR                8,1     4096      2 /
init      1 root  rtd    DIR                8,1     4096      2 /
init      1 root  txt    REG                8,1   265848 261189 /sbin/init
init      1 root  mem    REG                8,1    43616 581960 /lib/x86_64-linux-gnu/libnss_files-2.19.so
init      1 root  mem    REG                8,1    47760 555508 /lib/x86_64-linux-gnu/libnss_nis-2.19.so
init      1 root  mem    REG                8,1    97296 555504 /lib/x86_64-linux-gnu/libnsl-2.19.so
init      1 root  mem    REG                8,1    39824 555503 /lib/x86_64-linux-gnu/libnss_compat-2.19.so
init      1 root  mem    REG                8,1    14664 555500 /lib/x86_64-linux-gnu/libdl-2.19.so
init      1 root  mem    REG                8,1   252032 540246 /lib/x86_64-linux-gnu/libpcre.so.3.13.1
init      1 root  mem    REG                8,1   141574 555505 /lib/x86_64-linux-gnu/libpthread-2.19.so
init      1 root  mem    REG                8,1  1840928 581957 /lib/x86_64-linux-gnu/libc-2.19.so
init      1 root  mem    REG                8,1    31792 581956 /lib/x86_64-linux-gnu/librt-2.19.so
init      1 root  mem    REG                8,1    43464 527349 /lib/x86_64-linux-gnu/libjson-c.so.2.0.0
init      1 root  mem    REG                8,1   134296 527439 /lib/x86_64-linux-gnu/libselinux.so.1
init      1 root  mem    REG                8,1   281552 527323 /lib/x86_64-linux-gnu/libdbus-1.so.3.7.6
init      1 root  mem    REG                8,1    38920 527371 /lib/x86_64-linux-gnu/libnih-dbus.so.1.0.0
init      1 root  mem    REG                8,1    96280 527373 /lib/x86_64-linux-gnu/libnih.so.1.0.0
init      1 root  mem    REG                8,1   149120 555506 /lib/x86_64-linux-gnu/ld-2.19.so
init      1 root    0u   CHR                1,3      0t0   1029 /dev/null
init      1 root    1u   CHR                1,3      0t0   1029 /dev/null
init      1 root    2u   CHR                1,3      0t0   1029 /dev/null
init      1 root    3r  FIFO                0,9      0t0   8403 pipe
init      1 root    4w  FIFO                0,9      0t0   8403 pipe
init      1 root    5r  0000               0,10        0   7661 anon_inode
init      1 root    6r  0000               0,10        0   7661 anon_inode
init      1 root    7u  unix 0xffff8800b37c8780      0t0   8404 @/com/ubuntu/upstart
init      1 root    9u  unix 0xffff8800a14e7c00      0t0  12675 @/com/ubuntu/upstart
init      1 root   10u  unix 0xffff8800b37c9a40      0t0   8662 @/com/ubuntu/upstart
init      1 root   11u  unix 0xffff8800b37a1e00      0t0   9485 @/com/ubuntu/upstart
init      1 root   12w   REG                8,1      283 551619 /var/log/upstart/network-manager.log.1 (deleted)
init      1 root   14u  unix 0xffff8800b37a3c00      0t0  10329 @/com/ubuntu/upstart
init      1 root   16w   REG                8,1      451 522345 /var/log/upstart/systemd-logind.log.1 (deleted)
init      1 root   17u  unix 0xffff8800b37cb0c0      0t0   8637 socket
init      1 root   18u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   20u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   22u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   24w   REG                8,1      502 527289 /var/log/upstart/modemmanager.log.1 (deleted)
init      1 root   29u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   30u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   31w   REG                8,1      881 552236 /var/log/upstart/mysql.log.1 (deleted)
init      1 root   34u   CHR                5,2      0t0   1932 /dev/ptmx
init      1 root   36u   CHR                5,2      0t0   1932 /dev/ptmx
root@test:/home/juan#
now we can see a few more things, like:
  • Details of the FD, like its Type, Device it belongs to, etc.
  • We can see also some things that aren't really opened fd but some extra process information:
    • cwd current working directory
    • rtd root directory
    • txt init's binary code file
    • memory mapped files in this case bunch of system libraries. YES, these had a fd when they were mapped, but the fd was closed right after the mmap call was successful (you can see that checking this entry about strace).
Ok, now we know what a file descriptor or file handle is and how to identify them and map them to our processes. Is there any system wide limit for the file descriptors you can open?
 

Max open files, system wide:


If the answer for the previous question was now, I wouldn't have a reason to write this article in the first place I guess xD, therefore the answer is YES :P. The kernel is cool, and in order to play safe it has to set limits (I sound like a father now...) to avoid bigger problems.

The maximum number of open files the kernel can handle can be obtained from our beloved /proc, particularly in file file-nr under sys/fs directory. Here we can see the numbers for my current system:
root@test:/home/juan# cat /proc/sys/fs/file-nr
2944 0 298505
root@test:/home/juan#
These values mean the following:
  • First value (2944) indicates the number of allocated file descriptors, these are allocated dynamically by the kernel.
  • Second value (0) is the number of allocated but unused file descriptor. Kernels from 2.6.something free any unused fd, so this value should always be 0.
  • Third value (298505) indicates the maximum number of file descriptors that the kernel can allocate (also visible on file-max file).
Summing up, there are 2944 file descriptors allocated and in use at this precise moment. Almost 3k file descriptors allocated for about 142, interesting right?

Just for the sake of it, lets track down the process using the most number of file descriptors:
root@test:/home/juan# for i in `ps -Ao pid|grep -v PID`;do count=`ls /proc/$i/fd/ 2> /dev/null|wc -l`; echo "$count $i";done | sort -nr | head
61 1075
48 393
32 1264
31 1365
27 1132
24 1
21 440
20 1265
19 1325
19 1311
root@test:/home/juan#
there we see the top ten (first column is the number of FD and the second is the PID). Interestingly enough there's a process using 61 file descriptors, turns out I had mysqld installed on this VM (had no idea...):
root@test:/home/juan# ps aux|grep 1075
mysql     1075  0.1  1.9 624040 57792 ?        Ssl  10:38   0:07 /usr/sbin/mysqld
root      9664  0.0  0.0  15948  2232 pts/1    S+   12:35   0:00 grep --color=auto 1075
root@test:/home/juan#
 

Increasing the limit


If by any chance the almost 300k file descriptors the kernel allows to open is not enough (some busy systems may reach that limit) you will notice logs like "VFS: file-max limit reached" on dmesg and probably in messages or syslog files. In that case,  you can increase that limit using one of the following ways:
  • iminproductionpainchangeitrightnowgoddamnit way, by just updating /proc with the new value, like
root@test:/home/juan# echo 400000 > /proc/sys/fs/file-max
root@test:/home/juan# cat /proc/sys/fs/file-nr
3072    0       400000
root@test:/home/juan#
  • Or you can be more elegant and use sysctl command:
root@test:/home/juan# sysctl -w fs.file-max=500000
fs.file-max = 500000
root@test:/home/juan# cat /proc/sys/fs/file-nr
3072    0       500000
root@test:/home/juan#

In any case, don't forget to make the change persistent by doing:
root@test:/home/juan# echo "fs.file-max=500000" >> /etc/sysctl.conf
root@test:/home/juan#

If the error showing on your logs is instead "Too many open files" then the limit you've reached is most likely the ulimit for the user :D, which you know how to deal with because you've read this.

And that's about it!