Log filesystem changes

From Noah.org
Revision as of 16:08, 5 November 2014 by Root (Talk | contribs) (block_dump -- low level block device logging)

(diff) ← Older revision | Latest revision (diff) | Newer revision → (diff)
Jump to: navigation, search


Don't forget that file changes can be monitored on a per process basis using the strace command.

filesystem logging with inotify

Sometimes I want to see a log of every single filesystem access by any process. This can be done with inotify, but it is slow to register the root directory of a large filesystem.

This is slow:

inotifywatch --recursive --monitor /

In fact, that command may not work because Linux sets a limit on the number of objects that the kernel will watch. You can see and modify the limit via /proc/sys/fs/inotify/max_user_watches. The value 8192 seems typical. The following limits the watched objects to the root user's directory, which is usually small enough for the kernel to watch every change.

inotifywatch --recursive --monitor  /root

You may wish to watch just modify events. Otherwise, you may get a lot of noise from every single file open and close and file attribute change. Usually modify events are where the interesting things happen.

inotifywatch --recursive --monitor --event modify /root

fanotify and fatrace

The fanotify system is billed as a successor to inotify; although, it has not yet rendered inotify obsolete. Like inotify it watches and reocrds filesystem events. One of its advantages is that it does not have to be given a listen of objects to watch beforehand.

The tool fatrace does logging similar to inotifywatch, except that it is a little easier to use. It's big advantage is that it can watch the entire filesystem quickly and without limits on the number of objets. It is smart enough not to log filesystem events to its own logfile. It can include timestamps and limit it's scope to the filesystem mounted to the current directory. It's output can be a little noisy, but it's easy to filter out in an editor.

fatrace --current-mount --timestamp --output=fatrace.log &

block_dump -- low level block device logging

Would you like to log everything that goes in or out of the kernel block layer? There is a kernel option that logs everything to the kernel log (dmesg). This generates a lot of noise, so you wouldn't want to leave it on all the time. The following demonstrates how to turn on logging for the filesystem:

# Turn on block device logging to dmesg.
echo 1 > /proc/sys/vm/block_dump

# Use one of the following ways to observe the contents of dmesg:
tail -f /var/log/syslog
tail -f /var/log/kern.log
while true; do dmesg -c; sleep 1; done;

# Turn off block device logging to dmesg.
echo 0 > /proc/sys/vm/block_dump

This type of logging only logs the process and physical disk block number written to. This does not log the filename or any other application layer data. This may have limited use depending on your requirements. For example, some logging data might look like this:

Mar 25 23:03:54 vmh-prod-1 kernel: [532969.293789] blkback.44.xvda(1671): WRITE block 1048853728 on dm-30 (8 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.309566] touch(8926): READ block 172240168 on sda1 (16 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.309590] touch(8926): READ block 172240192 on sda1 (8 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.309598] touch(8926): READ block 172240224 on sda1 (8 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.309606] touch(8926): READ block 172240240 on sda1 (24 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.312571] jbd2/sda5-8(456): WRITE block 335845408 on sda5 (8 sectors)
Mar 25 23:03:57 vmh-prod-1 kernel: [532972.312598] jbd2/sda5-8(456): WRITE block 92540768 on sda5 (8 sectors)

blktrace -- another block device logging system

This is another tool that logs events at the block device level. Note that the documentation mentions a required kernel patch to use, but this patch is included in the latest kernels and is enabled by default in Debian and Ubuntu systems, so you should not have to do any kernel patching to use this tool. You do have to install the blktrace package to install the userland utility.

blktrace is similar to block_dump but it gives a block IO view from the perspective of the IO Scheduler.

The following is a basic way to use blktrace. Note that output is buffered any you may not see anything, or only partial output, until you hit CTRL-C to stop logging. Also note that you must give the device name you wish to watch, which is /dev/sda1 in this example. Note that you can also use the btrace command, which combines blktrace and blkparse in one command, so btrace /dev/sda1 is equivalent to the following commands.

blktrace -d /dev/sda1 -o - | blkparse -i -

From that you will get this type of output, which clearly requires that you read the documentation to understand.

root@vmh-prod-1:~# blktrace -d /dev/sda1 -o - | blkparse -i -
  8,0    2        1     0.000000000   354  A  WS 151332960 + 8 <- (8,1) 151330912
  8,1    2        2     0.000003060   354  Q  WS 151332960 + 8 [jbd2/sda1-8]
  8,1    2        3     0.000010372   354  G  WS 151332960 + 8 [jbd2/sda1-8]
  8,1    2        4     0.000011699   354  P   N [jbd2/sda1-8]
  8,1    2        5     0.000015149   354  I  WS 151332960 + 8 [jbd2/sda1-8]
  8,1    2        0     0.000018729     0  m   N cfq354S / insert_request
  8,1    2        0     0.000020256     0  m   N cfq354S / add_to_rr
  8,1    2        0     0.000023425     0  m   N cfq354S / preempt
  8,1    2        0     0.000024659     0  m   N cfq444A / slice expired t=1
  8,1    2        0     0.000025736     0  m   N cfq444A / resid=-6979
  8,1    2        0     0.000027569     0  m   N / served: vt=396630016 min_vt=396609536
  8,1    2        0     0.000029616     0  m   N cfq444A / sl_used=10 disp=3 charge=10 iops=0 sect=24
  8,1    2        0     0.000031039     0  m   N cfq444A / del_from_rr
  8,1    2        0     0.000033708     0  m   N cfq workload slice:25
  8,1    2        0     0.000035155     0  m   N cfq354S / set_active wl_prio:0 wl_type:1
  8,1    2        0     0.000036552     0  m   N cfq354S / Not idling. st->count:1
  8,1    2        0     0.000038246     0  m   N cfq354S / fifo=          (null)
  8,1    2        0     0.000039060     0  m   N cfq354S / dispatch_insert