Observing a hard-disk write in kernel space (with drivers/modules)

Question

Apologies in advance if this post is a bit dense/messy, but I'm having a hard time formulating it better... Basically, I would like to study what happens upon a hard disk write, and I'd like to know:

• Is my understanding below correct - and if not, where am I going wrong?
• Is there a better tool to "capture" log data, about all aspects happening on the PC, during a disk write?

In more detail - first, the OS I'm using is:

$ uname -a
Linux mypc 2.6.38-16-generic #67-Ubuntu SMP Thu Sep 6 18:00:43 UTC 2012 i686 i686 i386 GNU/Linux

So, I have the following simple (e.g. the usual checks for failure of operations are skipped) user-space C program, wtest.c:

#include <stdio.h>
#include <fcntl.h>  // O_CREAT, O_WRONLY, S_IRUSR

int main(void) {
  char filename[] = "/tmp/wtest.txt";
  char buffer[] = "abcd";
  int fd;
  mode_t perms = S_IRUSR|S_IWUSR|S_IRGRP|S_IWGRP|S_IROTH|S_IWOTH;

  fd = open(filename, O_RDWR|O_CREAT, perms);
  write(fd,buffer,4);
  close(fd);

  return 0;
}

I build this with gcc -g -O0 -o wtest wtest.c. Now, since I'm trying to write to /tmp, I note that it is a directory under the root / - so I check mount:

$ mount
/dev/sda5 on / type ext4 (rw,errors=remount-ro,commit=0)
...
/dev/sda6 on /media/disk1 type ext4 (rw,uhelper=hal,commit=0)
/dev/sda7 on /media/disk2 type ext3 (rw,nosuid,nodev,uhelper=udisks,commit=0,commit=0,commit=0,commit=0,commit=0,commit=0)
...

So, my root filesystem / is one partition of the /dev/sda device (and I'm using other partitions as "standalone" disks/mounts, too). To find the driver for this device, I use hwinfo:

$ hwinfo --disk
...
19: IDE 00.0: 10600 Disk
...
  SysFS ID: /class/block/sda
  SysFS BusID: 0:0:0:0
...
  Hardware Class: disk
  Model: "FUJITSU MHY225RB"
...
  Driver: "ata_piix", "sd"
  Driver Modules: "ata_piix"
  Device File: /dev/sda
...
  Device Number: block 8:0-8:15
...

So, the /dev/sda hard disk is apparently handled by ata_piix (and sd) driver.

$ grep 'ata_piix\| sd' <(gunzip </var/log/syslog.2.gz)
Jan 20 09:28:31 mypc kernel: [    1.963846] ata_piix 0000:00:1f.2: version 2.13
Jan 20 09:28:31 mypc kernel: [    1.963901] ata_piix 0000:00:1f.2: PCI INT B -> GSI 19 (level, low) -> IRQ 19
Jan 20 09:28:31 mypc kernel: [    1.963912] ata_piix 0000:00:1f.2: MAP [ P0 P2 P1 P3 ]
Jan 20 09:28:31 mypc kernel: [    2.116038] ata_piix 0000:00:1f.2: setting latency timer to 64
Jan 20 09:28:31 mypc kernel: [    2.116817] scsi0 : ata_piix
Jan 20 09:28:31 mypc kernel: [    2.117068] scsi1 : ata_piix
Jan 20 09:28:31 mypc kernel: [    2.529065] sd 0:0:0:0: [sda] 488397168 512-byte logical blocks: (250 GB/232 GiB)
Jan 20 09:28:31 mypc kernel: [    2.529104] sd 0:0:0:0: Attached scsi generic sg0 type 0
Jan 20 09:28:31 mypc kernel: [    2.529309] sd 0:0:0:0: [sda] Write Protect is off
Jan 20 09:28:31 mypc kernel: [    2.529319] sd 0:0:0:0: [sda] Mode Sense: 00 3a 00 00
Jan 20 09:28:31 mypc kernel: [    2.529423] sd 0:0:0:0: [sda] Write cache: enabled, read cache: enabled, doesn't support DPO or FUA
Jan 20 09:28:31 mypc kernel: [    2.674783]  sda: sda1 sda2 < sda5 sda6 sda7 sda8 sda9 sda10 >
Jan 20 09:28:31 mypc kernel: [    2.676075] sd 0:0:0:0: [sda] Attached SCSI disk
Jan 20 09:28:31 mypc kernel: [    4.145312] sd 2:0:0:0: Attached scsi generic sg1 type 0
Jan 20 09:28:31 mypc kernel: [    4.150596] sd 2:0:0:0: [sdb] Attached SCSI removable disk

I have to pull from older syslog as I suspend a lot, but the above seems like the proper snippet from the syslog at boot time, where the ata_piix (and sd) driver kicks in for the first time.

My first point of confusion is that I cannot otherwise observe the ata_piix or sd drivers:

$ lsmod | grep 'ata_piix\| sd'
$
$ modinfo sd
ERROR: modinfo: could not find module sd
$ modinfo ata_piix
ERROR: modinfo: could not find module ata_piix

So my first question is - why cannot I observe the ata_piix module here, only in boot-time logs? Is it because ata_piix (and sd) are built as built-in drivers in the (monolithic) kernel, as opposed to being built as (loadable) .ko kernel modules?

Right - so now, I'm trying to observe what happens upon running the program with ftrace Linux built-in function tracer.

sudo bash -c '
KDBGPATH="/sys/kernel/debug/tracing"
echo function_graph > $KDBGPATH/current_tracer
echo funcgraph-abstime > $KDBGPATH/trace_options
echo funcgraph-proc > $KDBGPATH/trace_options
echo 0 > $KDBGPATH/tracing_on
echo > $KDBGPATH/trace
echo 1 > $KDBGPATH/tracing_on ; ./wtest ; echo 0 > $KDBGPATH/tracing_on
cat $KDBGPATH/trace > wtest.ftrace
'

... and here is a snippet of the ftrace log concerning the write:

 4604.352690 |   0)  wtest-31632   |               |  sys_write() {
 4604.352690 |   0)  wtest-31632   |   0.750 us    |    fget_light();
 4604.352692 |   0)  wtest-31632   |               |    vfs_write() {
 4604.352693 |   0)  wtest-31632   |               |      rw_verify_area() {
 4604.352693 |   0)  wtest-31632   |               |        security_file_permission() {
 4604.352694 |   0)  wtest-31632   |               |          apparmor_file_permission() {
 4604.352695 |   0)  wtest-31632   |   0.811 us    |            common_file_perm();
 4604.352696 |   0)  wtest-31632   |   2.198 us    |          }
 4604.352697 |   0)  wtest-31632   |   3.573 us    |        }
 4604.352697 |   0)  wtest-31632   |   4.979 us    |      }
 4604.352698 |   0)  wtest-31632   |               |      do_sync_write() {
 4604.352699 |   0)  wtest-31632   |               |        ext4_file_write() {
 4604.352700 |   0)  wtest-31632   |               |          generic_file_aio_write() {
 4604.352701 |   0)  wtest-31632   |               |            mutex_lock() {
 4604.352701 |   0)  wtest-31632   |   0.666 us    |              _cond_resched();
 4604.352703 |   0)  wtest-31632   |   1.994 us    |            }
 4604.352704 |   0)  wtest-31632   |               |            __generic_file_aio_write() {
...
 4604.352728 |   0)  wtest-31632   |               |              file_update_time() {
...
 4604.352732 |   0)  wtest-31632   |   0.756 us    |                mnt_want_write_file();
 4604.352734 |   0)  wtest-31632   |               |                __mark_inode_dirty() {
...
 4604.352750 |   0)  wtest-31632   |               |                    ext4_mark_inode_dirty() {
 4604.352750 |   0)  wtest-31632   |   0.679 us    |                      _cond_resched();
 4604.352752 |   0)  wtest-31632   |               |                      ext4_reserve_inode_write() {
...
 4604.352777 |   0)  wtest-31632   |               |                        __ext4_journal_get_write_access() {
...
 4604.352795 |   0)  wtest-31632   |               |                      ext4_mark_iloc_dirty() {
...
 4604.352806 |   0)  wtest-31632   |               |                    __ext4_journal_stop() {
...
 4604.352821 |   0)  wtest-31632   |   0.684 us    |                mnt_drop_write();
 4604.352822 |   0)  wtest-31632   | + 93.541 us   |              }
 4604.352823 |   0)  wtest-31632   |               |              generic_file_buffered_write() {
 4604.352824 |   0)  wtest-31632   |   0.654 us    |                iov_iter_advance();
 4604.352825 |   0)  wtest-31632   |               |                generic_perform_write() {
 4604.352826 |   0)  wtest-31632   |   0.709 us    |                  iov_iter_fault_in_readable();
 4604.352828 |   0)  wtest-31632   |               |                  ext4_da_write_begin() {
 4604.352829 |   0)  wtest-31632   |               |                    ext4_journal_start_sb() {
...
 4604.352847 |   0)  wtest-31632   |   1.453 us    |                    __block_write_begin();
 4604.352849 |   0)  wtest-31632   | + 21.128 us   |                  }
 4604.352849 |   0)  wtest-31632   |               |                  iov_iter_copy_from_user_atomic() {
 4604.352850 |   0)  wtest-31632   |               |                    __kmap_atomic() {
...
 4604.352863 |   0)  wtest-31632   |   0.672 us    |                  mark_page_accessed();
 4604.352864 |   0)  wtest-31632   |               |                  ext4_da_write_end() {
 4604.352865 |   0)  wtest-31632   |               |                    generic_write_end() {
 4604.352866 |   0)  wtest-31632   |               |                      block_write_end() {
...
 4604.352893 |   0)  wtest-31632   |               |                    __ext4_journal_stop() {
...
 4604.352909 |   0)  wtest-31632   |   0.655 us    |            mutex_unlock();
 4604.352911 |   0)  wtest-31632   |   0.727 us    |            generic_write_sync();
 4604.352912 |   0)  wtest-31632   | ! 212.259 us  |          }
 4604.352913 |   0)  wtest-31632   | ! 213.845 us  |        }
 4604.352914 |   0)  wtest-31632   | ! 215.286 us  |      }
 4604.352914 |   0)  wtest-31632   |   0.685 us    |      __fsnotify_parent();
 4604.352916 |   0)  wtest-31632   |               |      fsnotify() {
 4604.352916 |   0)  wtest-31632   |   0.907 us    |        __srcu_read_lock();
 4604.352918 |   0)  wtest-31632   |   0.685 us    |        __srcu_read_unlock();
 4604.352920 |   0)  wtest-31632   |   3.958 us    |      }
 4604.352920 |   0)  wtest-31632   | ! 228.409 us  |    }
 4604.352921 |   0)  wtest-31632   | ! 231.334 us  |  }

This is my second point of confusion - I can observe the user-space write() resulted with a kernel-space sys_write(), as expected; and within the sys_write(), I observe security-related functions (e.g. apparmor_file_permission()), "generic" write functions (e.g. generic_file_aio_write()), ext4 filesystem related functions (e.g. ext4_journal_start_sb()) - but I do not observe anything related to ata_piix (or sd) drivers ?!

The page Tracing and Profiling - Yocto Project suggests using the blk tracer in ftrace to get more information about block device operation, but it reports nothing for me with this example. Also, Linux Filesystem Drivers - Annon Inglorion (tutorfs) suggests that filesystems are (can?) also (be) implemented as kernel modules/drivers, and I'm guessing that is the case for ext4 as well.

Finally, I could have sworn that I have earlier observed the driver name in square brackets next to the function shown by the function_graph tracer, but I guess I had mixed things up - it can probably appear like that in stack (back)traces, but not in the function graph. Furthermore, I can inspect /proc/kallsyms:

$ grep 'piix\| sd\|psmouse' /proc/kallsyms
...
00000000 d sd_ctl_dir
00000000 d sd_ctl_root
00000000 d sdev_class
00000000 d sdev_attr_queue_depth_rw
00000000 d sdev_attr_queue_ramp_up_period
00000000 d sdev_attr_queue_type_rw
00000000 d sd_disk_class
...
00000000 t piix_init_sata_map
00000000 t piix_init_sidpr
00000000 t piix_init_one
00000000 t pci_fixup_piix4_acpi
...
00000000 t psmouse_show_int_attr        [psmouse]
00000000 t psmouse_protocol_by_type     [psmouse]
00000000 r psmouse_protocols    [psmouse]
00000000 t psmouse_get_maxproto [psmouse]
...

... and checking with source Linux/drivers/ata/ata_piix.c, confirm that e.g. piix_init_sata_map is indeed a function in ata_piix. Which should probably tell me that: modules that are compiled in the kernel (so they become a part of the monolithic kernel) "lose" the information about which module they come from; however, the loadable modules which are built as separate .ko kernel objects, preserve that information (e.g. [psmouse] shown above in square brackets). Thus, also ftrace could only show "originating module" information, only for those functions coming from loadable kernel modules. Is this correct?

The above taken into consideration, this is the understanding that I have of the process currently:

• At boot time, the ata_piix driver establishes a DMA (?) memory mapping between /dev/sda and the hard disk
  • because of this, all future accesses to /dev/sda via ata_piix will be transparent to the kernel (that is, not traceable) - since all the kernel would see, are just reads/writes to memory locations (not necessarily calls to specific traceable kernel functions), which are not reported by function_graph tracer
• At boot time, the sd driver will furthermore "parse" the partitions of /dev/sda, make them available, and possibly handle the memory mappings between partitions <-> disk device
  • again, this should make the access operations via sd transparent to the kernel
• Since both ata_piix and sd are compiled in-kernel, even if some of their functions do end up being captured by ftrace, we cannot get an information of which module those functions would come from (apart from "manual" correlation with source files)
• Later on, mount establishes a relationship/binding between a partition, and the corresponding filesystem driver (in this case ext4)
  • from this point on, all of the accesses to the mounted filesystem would be handled by ext4 functions - which are traceable by the kernel; but as ext4 is compiled in-kernel, the tracer cannot give us the originating module information
• So, the observed "generic" writes, called via ext4 functions, would ultimately access memory locations, whose mapping is established by ata_piix - but other than that, ata_piix doesn't interfere directly with data transfers (it being probably handled by DMA (outside of the processor(s), and thus transparent to it).

Is this understanding correct?

Some related subquestions:

• In my setup above, I can identify a PCI device driver (ata_piix) and a filesystem driver (ext4); but are there character or block drivers used somewhere on the "write" execution path, and if so, which are they?
• Which of those drivers would handle caching (so unnecessary disk operations are skipped or optimized?)
• I know from before that /dev/shm is a filesystem in RAM; mount | grep shm for me reports: none on /dev/shm type tmpfs (rw,nosuid,nodev). Does that mean that - in contrast to /dev/sda - the shm filesystem simply lacks the (DMA) mapping from "its own" adrresses to bus addresses towards a device; and thus all accesses via the tmpfs filesystem driver end up in actual RAM?

Answer 1

You've asked way too much in one question—well, technically not, as I guess "is this understanding correct" can be answered quickly: no. But that's not a useful answer.

First, you're right about ata_piix and sd_mod apparently being compiled-in to your kernel. That's a choice you make configuring the kernel—you can omit it, include it, or include it as a module. (Same with ext4).

Second, you have assumed writes to be far simpler than they actually are. The basic outline of how a write works is that the filesystem code puts the data to be written in memory, as part of the buffer-cache, and marks it as needs-to-be-written ("dirty"). (Unless there is already too much of that in RAM, in which case it actually is forced to do the write...)

Later, various things (such as the bdflush kernel thread) actually flush the dirty pages to disk. This is when you'd see calls through sd, scsi, libata, ata_piix, io schedulers, PCI, etc. While there is very likely DMA involved in that write-out, it's of the data to be transferred, and maybe the command. But disk writes, at least in SATA, are handled by sending commands which basically mean "write sector X with data Y". But it's definitely not handled by memory-mapping the entire disk (consider: you can use disks far larger than 4GiB on 32-bit machines).

Caching is handled by the memory management subsystem (not a driver), in conjunction with the filesystem, block layer, etc.

tmpfs is special, it is basically entirely cache. Its just special cache that is never discarded or written back (though it can be swapped out). You can find the code in mm/shmem.c and several other places (try ack-grep --cc CONFIG_TMPFS to find them).

Basically, writing to disk goes through a good portion of the kernel's subsystems; networking is the only major one I can think of that isn't involved in your example. Properly explaining it requires a book-length effort; I recommend looking for one.

Answer 2

So my first question is - why cannot I observe the ata_piix module here, only in boot-time logs? Is it because ata_piix (and sd) are built as built-in drivers in the (monolithic) kernel, as opposed to being built as (loadable) .ko kernel modules?

You don't have to guess what your configuration is. On my machine I have

$ uname -a
Linux orwell 3.2.0-4-amd64 #1 SMP Debian 3.2.51-1 x86_64 GNU/Linux

The config file is for this kernel is located at /boot/config-3.2.0-4-amd64.

You asked about ata_piix. Searching the above .config file, we see CONFIG_ATA_PIIX=m. we can confirm this by doing

dlocate ata_piix.ko   

alternatively

dpkg -S ata_piix.ko

linux-image-3.2.0-4-amd64: /lib/modules/3.2.0-4-amd64/kernel/drivers/ata/ata_piix.ko

So at least in my kernel, it is a module.