Added function traces of the loop device kernel module

5 files changed, 101 insertions, 0 deletions

diff --git a/analysis/loop/ftrace/README.md b/analysis/loop/ftrace/README.md
new file mode 100644
index 0000000..6ac9cd7
--- /dev/null
+++ b/analysis/loop/ftrace/README.md
@@ -0,0 +1,29 @@
+# Tracing the loop device kernel module
+
+The loop device kernel module can be traced with the *ftrace* framework of the
+Linux kernel. Therefore, *ftrace* must be compiled into the Linux kernel and the
+user space module *trace-cmd* is necessary.
+
+
+## Creating the trace file
+
+Each loop device specific operation can be traced with the following command
+```bash
+trace-cmd record -p function_graph --module loop -o [trace file] [cmd]
+```
+where `[trace file]` is the created trace file and `[cmd]` is one of the
+following loop device operation:
+  * add loop device: `losetup -f test.img`
+  * read from loop device: `dd if=/dev/loop0 bs=512 count=1 of=tmp.img`
+  * write to loop device: `dd of=/dev/loop0 bs=512 count=1 if=tmp.img`
+  * remove loop device: `losetup -D`
+
+
+## Viewing the trace file
+
+The created trace file can be viewed on the command line with the following
+command:
+```bash
+trace-cmd report -i [trace file]
+```
+where `[trace file]` is the already created trace file.
diff --git a/analysis/loop/ftrace/loop_device_add.txt b/analysis/loop/ftrace/loop_device_add.txt
new file mode 100644
index 0000000..e77e5ca
--- /dev/null
+++ b/analysis/loop/ftrace/loop_device_add.txt
@@ -0,0 +1,28 @@
+      losetup-26893 [000] 23442.832217: funcgraph_entry:                  |  loop_control_ioctl() {
+      losetup-26893 [000] 23442.832219: funcgraph_entry:                  |    loop_lookup.part.7() {
+      losetup-26893 [000] 23442.832220: funcgraph_entry:        0.426 us  |      find_free_cb();
+      losetup-26893 [000] 23442.832221: funcgraph_exit:         2.140 us  |    }
+      losetup-26893 [000] 23442.832221: funcgraph_exit:         5.796 us  |  }
+      losetup-26893 [000] 23442.832366: funcgraph_entry:        0.817 us  |  lo_open();
+      losetup-26893 [000] 23442.832374: funcgraph_entry:                  |  lo_ioctl() {
+      losetup-26893 [000] 23442.832375: funcgraph_entry:                  |    loop_set_fd() {
+      losetup-26893 [000] 23442.832377: funcgraph_entry:        0.230 us  |      loop_validate_file();
+      losetup-26893 [000] 23442.832377: funcgraph_entry:  !   269.316 us  |      loop_prepare_queue();
+      losetup-26893 [000] 23442.832649: funcgraph_entry:        0.667 us  |      __loop_update_dio();
+        loop0-26894 [001] 23442.832714: funcgraph_entry:                  |  loop_kthread_worker_fn() {
+      losetup-26893 [001] 23442.834887: funcgraph_exit:   #  2511.581 us  |    }
+      losetup-26893 [001] 23442.834888: funcgraph_exit:   #  2513.226 us  |  }
+      losetup-26893 [001] 23442.834893: funcgraph_entry:                  |  lo_ioctl() {
+      losetup-26893 [001] 23442.834894: funcgraph_entry:                  |    loop_set_status64() {
+      losetup-26893 [001] 23442.834894: funcgraph_entry:                  |      loop_set_status() {
+systemd-udevd-26895 [000] 23442.836880: funcgraph_entry:                  |  lo_open() {
+      losetup-26893 [001] 23442.858173: funcgraph_entry:        3.027 us  |        loop_release_xfer();
+      losetup-26893 [001] 23442.858176: funcgraph_entry:        2.220 us  |        loop_config_discard();
+      losetup-26893 [001] 23442.858179: funcgraph_entry:        0.786 us  |        __loop_update_dio();
+      losetup-26893 [001] 23442.858187: funcgraph_exit:   # 23292.836 us  |      }
+      losetup-26893 [001] 23442.858187: funcgraph_exit:   # 23293.764 us  |    }
+      losetup-26893 [001] 23442.858188: funcgraph_exit:   # 23294.529 us  |  }
+systemd-udevd-26895 [000] 23442.858250: funcgraph_exit:   # 21370.451 us  |  }
+      losetup-26893 [001] 23442.858266: funcgraph_entry:        1.190 us  |  lo_release();
+systemd-udevd-267   [000] 23442.859186: funcgraph_entry:        1.873 us  |  lo_open();
+systemd-udevd-267   [000] 23442.859223: funcgraph_entry:        0.833 us  |  lo_release();
diff --git a/analysis/loop/ftrace/loop_device_read.txt b/analysis/loop/ftrace/loop_device_read.txt
new file mode 100644
index 0000000..72bd066
--- /dev/null
+++ b/analysis/loop/ftrace/loop_device_read.txt
@@ -0,0 +1,11 @@
+   dd-26638 [000] 22209.671242: funcgraph_entry:        4.161 us  |  lo_open();
+   dd-26638 [000] 22209.671632: funcgraph_entry:  +    24.903 us  |  loop_queue_rq();
+loop0-13110 [001] 22209.671764: funcgraph_entry:                  |  loop_queue_work() {
+loop0-13110 [001] 22209.671781: funcgraph_entry:                  |    loop_handle_cmd() {
+loop0-13110 [001] 22209.671782: funcgraph_entry:                  |      do_req_filebacked() {
+loop0-13110 [001] 22209.671782: funcgraph_entry:  +    22.980 us  |        lo_read_simple();
+loop0-13110 [001] 22209.671805: funcgraph_exit:   +    23.625 us  |      }
+loop0-13110 [001] 22209.671811: funcgraph_exit:   +    29.815 us  |    }
+loop0-13110 [001] 22209.671811: funcgraph_exit:   +    47.686 us  |  }
+gmain-762   [000] 22209.671820: funcgraph_entry:  +    23.196 us  |  lo_complete_rq();
+   dd-26638 [000] 22209.672127: funcgraph_entry:  # 18143.654 us  |  lo_release();
diff --git a/analysis/loop/ftrace/loop_device_remove.txt b/analysis/loop/ftrace/loop_device_remove.txt
new file mode 100644
index 0000000..4126540
--- /dev/null
+++ b/analysis/loop/ftrace/loop_device_remove.txt
@@ -0,0 +1,9 @@
+losetup-26659 [000] 22264.651607: funcgraph_entry:        3.393 us  |  lo_open();
+losetup-26659 [000] 22264.651622: funcgraph_entry:                  |  lo_ioctl() {
+losetup-26659 [000] 22264.651622: funcgraph_entry:                  |    loop_clr_fd() {
+losetup-26659 [000] 22264.651623: funcgraph_entry:                  |      __loop_clr_fd() {
+losetup-26659 [000] 22264.689771: funcgraph_entry:        3.844 us  |        loop_release_xfer();
+losetup-26659 [001] 22264.691239: funcgraph_exit:   # 39615.444 us  |      }
+losetup-26659 [001] 22264.691241: funcgraph_exit:   # 39619.125 us  |    }
+losetup-26659 [001] 22264.691242: funcgraph_exit:   # 39620.534 us  |  }
+losetup-26659 [001] 22264.691499: funcgraph_entry:        2.186 us  |  lo_release();
diff --git a/analysis/loop/ftrace/loop_device_write.txt b/analysis/loop/ftrace/loop_device_write.txt
new file mode 100644
index 0000000..52086f9
--- /dev/null
+++ b/analysis/loop/ftrace/loop_device_write.txt
@@ -0,0 +1,24 @@
+           dd-27058 [000] 24561.155144: funcgraph_entry:        2.976 us  |  lo_open();
+ kworker/0:1H-213   [000] 24561.155252: funcgraph_entry:  +    11.023 us  |  loop_queue_rq();
+        loop0-26894 [000] 24561.155273: funcgraph_entry:                  |    loop_queue_work() {
+        loop0-26894 [000] 24561.155273: funcgraph_entry:                  |      loop_handle_cmd() {
+        loop0-26894 [000] 24561.155273: funcgraph_entry:                  |        do_req_filebacked() {
+        loop0-26894 [000] 24561.155274: funcgraph_entry:        7.457 us  |          lo_read_simple();
+        loop0-26894 [000] 24561.155281: funcgraph_exit:         7.969 us  |        }
+        loop0-26894 [000] 24561.155287: funcgraph_exit:   +    14.226 us  |      }
+        loop0-26894 [000] 24561.155287: funcgraph_exit:   +    14.784 us  |    }
+  ksoftirqd/0-9     [000] 24561.155296: funcgraph_entry:  +    14.422 us  |  lo_complete_rq();
+           dd-27058 [000] 24561.155414: funcgraph_entry:        8.161 us  |  loop_queue_rq();
+        loop0-26894 [000] 24561.155429: funcgraph_entry:                  |    loop_queue_work() {
+        loop0-26894 [000] 24561.155429: funcgraph_entry:                  |      loop_handle_cmd() {
+        loop0-26894 [000] 24561.155430: funcgraph_entry:                  |        do_req_filebacked() {
+        loop0-26894 [000] 24561.155430: funcgraph_entry:                  |          lo_write_simple() {
+        loop0-26894 [000] 24561.155430: funcgraph_entry:  +    54.236 us  |            lo_write_bvec();
+        loop0-26894 [000] 24561.155485: funcgraph_exit:   +    54.952 us  |          }
+        loop0-26894 [000] 24561.155485: funcgraph_exit:   +    55.403 us  |        }
+        loop0-26894 [000] 24561.155490: funcgraph_exit:   +    60.666 us  |      }
+        loop0-26894 [000] 24561.155490: funcgraph_exit:   +    61.088 us  |    }
+  ksoftirqd/0-9     [000] 24561.155743: funcgraph_entry:  +    19.316 us  |  lo_complete_rq();
+           dd-27058 [000] 24561.155828: funcgraph_entry:  # 34575.481 us  |  lo_release();
+systemd-udevd-267   [001] 24561.190463: funcgraph_entry:        2.223 us  |  lo_open();
+systemd-udevd-267   [001] 24561.190505: funcgraph_entry:                  |  lo_release() {