From f1cb688da5687fd7cec704af1d38058368525ca4 Mon Sep 17 00:00:00 2001 From: Manuel Bentele Date: Wed, 5 Jun 2019 01:24:20 +0200 Subject: Added function traces of the loop device kernel module --- analysis/loop/ftrace/README.md | 29 +++++++++++++++++++++++++++++ analysis/loop/ftrace/loop_device_add.txt | 28 ++++++++++++++++++++++++++++ analysis/loop/ftrace/loop_device_read.txt | 11 +++++++++++ analysis/loop/ftrace/loop_device_remove.txt | 9 +++++++++ analysis/loop/ftrace/loop_device_write.txt | 24 ++++++++++++++++++++++++ 5 files changed, 101 insertions(+) create mode 100644 analysis/loop/ftrace/README.md create mode 100644 analysis/loop/ftrace/loop_device_add.txt create mode 100644 analysis/loop/ftrace/loop_device_read.txt create mode 100644 analysis/loop/ftrace/loop_device_remove.txt create mode 100644 analysis/loop/ftrace/loop_device_write.txt 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() { -- cgit v1.2.3-55-g7522