All of lore.kernel.org
 help / color / mirror / Atom feed
From: Arnaldo Carvalho de Melo <acme@kernel.org>
To: linux-btrace@vger.kernel.org
Subject: Re: [PATCH 18/31] blktrace: doc: alternatives to blktrace traditional tooling
Date: Fri, 27 Apr 2018 19:40:53 +0000	[thread overview]
Message-ID: <20180427194053.GA17295@kernel.org> (raw)
In-Reply-To: <20180427130738.102806-19-maier@linux.ibm.com>

Em Fri, Apr 27, 2018 at 03:07:25PM +0200, Steffen Maier escreveu:
> Signed-off-by: Steffen Maier <maier@linux.ibm.com>
> Cc: Arnaldo Carvalho de Melo <acme@kernel.org>
> Cc: Li Zefan <lizefan@huawei.com>
> Cc: Steven Rostedt <rostedt@goodmis.org>
> Cc: Ingo Molnar <mingo@redhat.com>
> Cc: Peter Zijlstra <peterz@infradead.org>
> Cc: Christoph Hellwig <hch@lst.de>

Interesting, I'd suggest adding 'perf trace' to that mix, that is a strace like
perf tool that can mix and match syscalls formatted strace-like + other events,
such as tracepoints, with the record perf.data, process it later, or do it
live, like strace, but with a vastly lower overhead and not just for a workload
started from it or a pid, but supporting the other targets perf supports:
system wide, CPU wide, cgroups, etc.

For instance, to see the block lifetime of a workload that
calls fsync, intermixed to the strace like output of the 'read' and 'write'
syscalls:

[root@jouet bpf]# perf trace -e read,write,block:* dd if=/etc/passwd of=bla conv=fsync
     0.054 ( 0.004 ms): dd/24556 read(fd: 3, buf: 0x7fff83d09318, count: 832                           ) = 832
     0.521 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.524 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.528 (         ): block:block_touch_buffer:253,2 sector\x1492603 size@96
     0.534 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.550 ( 0.007 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.559 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.562 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.574 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.578 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.559 ( 0.023 ms): dd/24556  ... [continued]: write()) = 512
     0.584 ( 0.003 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.589 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.592 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.594 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.589 ( 0.007 ms): dd/24556  ... [continued]: write()) = 512
     0.598 ( 0.002 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.603 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.606 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.608 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.603 ( 0.008 ms): dd/24556  ... [continued]: write()) = 512
     0.613 ( 0.002 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.617 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.621 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.623 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.617 ( 0.009 ms): dd/24556  ... [continued]: write()) = 512
     0.629 ( 0.003 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.634 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.637 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.639 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.634 ( 0.008 ms): dd/24556  ... [continued]: write()) = 512
     0.644 ( 0.002 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.649 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.652 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.654 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.649 ( 0.008 ms): dd/24556  ... [continued]: write()) = 512
     0.659 ( 0.003 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 512
     0.664 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 512      ) ...
     0.667 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.669 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.664 ( 0.007 ms): dd/24556  ... [continued]: write()) = 512
     0.674 ( 0.002 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 298
     0.679 ( 0.005 ms): dd/24556 read(buf: 0x55c3ca055000, count: 512                                  ) = 0
     0.686 (         ): dd/24556 write(fd: 1</home/acme/bpf/bla>, buf: 0x55c3ca057000, count: 298      ) ...
     0.689 (         ): block:block_dirty_buffer:253,2 sector\x18446744073709486080 size@96
     0.691 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.686 ( 0.008 ms): dd/24556  ... [continued]: write()) = 298
     0.716 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.719 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.729 (         ): block:block_touch_buffer:253,2 sector\x1584 size@96
     0.735 (         ): block:block_bio_queue:253,2 WS 63627608 + 8 [dd]
     0.740 (         ): block:block_bio_remap:8,0 WS 79620440 + 8 <- (253,2) 63627608
     0.743 (         ): block:block_bio_remap:8,0 WS 196985176 + 8 <- (8,6) 79620440
     0.746 (         ): block:block_bio_queue:8,0 WS 196985176 + 8 [dd]
     0.756 (         ): block:block_getrq:8,0 WS 196985176 + 8 [dd]
     0.759 (         ): block:block_plug:[dd]
     0.764 (         ): block:block_rq_insert:8,0 WS 4096 () 196985176 + 8 [dd]
     0.768 (         ): block:block_unplug:[dd] 1
     0.771 (         ): block:block_rq_issue:8,0 WS 4096 () 196985176 + 8 [dd]
     8.864 ( 0.006 ms): dd/24556 read(buf: 0x55c3ca057910, count: 4096                                 ) = 2997
     8.891 ( 0.003 ms): dd/24556 read(buf: 0x55c3ca057910, count: 4096                                 ) = 0
7+1 records in
7+1 records out
3882 bytes (3.9 kB, 3.8 KiB) copied, 0.00845109 s, 459 kB/s
     8.985 ( 0.008 ms): dd/24556 write(fd: 2</dev/pts/10>, buf: 0x7fff83d07760, count: 31              ) = 31
     9.013 ( 0.005 ms): dd/24556 write(fd: 2</dev/pts/10>, buf: 0x7fff83d06f90, count: 59              ) = 59
     9.021 ( 0.004 ms): dd/24556 write(fd: 2</dev/pts/10>, buf: 0x7f032f1946e3, count: 1               ) = 1
[root@jouet bpf]#

If one wants instead to concentrate on the callchains leading to the block_rq_issue:

[root@jouet bpf]# perf trace --no-syscalls -e block:*rq_issue/call-graph=dwarf,max-stack\x10/ dd if=/etc/passwd of=bla conv=fsync
7+1 records in
7+1 records out
3882 bytes (3.9 kB, 3.8 KiB) copied, 0.010108 s, 384 kB/s
no symbols found in /usr/bin/dd, maybe install a debug package?
     0.000 block:block_rq_issue:8,0 WS 4096 () 197218728 + 8 [dd]
                                       blk_peek_request ([kernel.kallsyms])
                                       fsync (/usr/lib64/libc-2.26.so)
                                       [0xffffaa100818045d] (/usr/bin/dd)
                                       __libc_start_main (/usr/lib64/libc-2.26.so)
                                       [0xffffaa1008180d99] (/usr/bin/dd)
[root@jouet bpf]# 

installing the debuginfo for the coreutils package, where dd lives, would give more info, etc.

Since this is an ext4 filesystem, lets add its *write* routines to the mix:

[root@jouet bpf]# perf trace --no-syscalls -e ext4:*write*/call-graph=dwarf/,block:*rq_issue/call-graph=dwarf/ dd if=/etc/passwd of=bla conv=fsync |& tail -18
     0.215 ext4:ext4_da_write_pages:dev 253,2 ino 8437 first_page 1 nr_to_write 9223372036854775806 sync_mode 1
                                       ext4_writepages ([kernel.kallsyms])
                                       fsync (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f16310445d] (/usr/bin/dd)
                                       __libc_start_main (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f163104d99] (/usr/bin/dd)
     0.231 block:block_rq_issue:8,0 WS 4096 () 197703696 + 8 [dd]
                                       blk_peek_request ([kernel.kallsyms])
                                       fsync (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f16310445d] (/usr/bin/dd)
                                       __libc_start_main (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f163104d99] (/usr/bin/dd)
     0.249 ext4:ext4_writepages_result:dev 253,2 ino 8437 ret 0 pages_written 1 pages_skipped 0 sync_mode 1 writeback_index 1
                                       ext4_writepages ([kernel.kallsyms])
                                       fsync (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f16310445d] (/usr/bin/dd)
                                       __libc_start_main (/usr/lib64/libc-2.26.so)
                                       [0xffffa9f163104d99] (/usr/bin/dd)
[root@jouet bpf]#

And if we replace that --no-syscalls with *sync, we'd get as the last line this:

     0.752 ( 7.651 ms): dd/24974  ... [continued]: fsync()) = 0

:-)

- Arnaldo

  reply	other threads:[~2018-04-27 19:40 UTC|newest]

Thread overview: 4+ messages / expand[flat|nested]  mbox.gz  Atom feed  top
2018-04-27 13:07 [PATCH 18/31] blktrace: doc: alternatives to blktrace traditional tooling Steffen Maier
2018-04-27 19:40 ` Arnaldo Carvalho de Melo [this message]
2018-05-04 16:10 ` Steffen Maier
2018-05-04 18:31 ` Arnaldo Carvalho de Melo

Reply instructions:

You may reply publicly to this message via plain-text email
using any one of the following methods:

* Save the following mbox file, import it into your mail client,
  and reply-to-all from there: mbox

  Avoid top-posting and favor interleaved quoting:
  https://en.wikipedia.org/wiki/Posting_style#Interleaved_style

* Reply using the --to, --cc, and --in-reply-to
  switches of git-send-email(1):

  git send-email \
    --in-reply-to=20180427194053.GA17295@kernel.org \
    --to=acme@kernel.org \
    --cc=linux-btrace@vger.kernel.org \
    /path/to/YOUR_REPLY

  https://kernel.org/pub/software/scm/git/docs/git-send-email.html

* If your mail client supports setting the In-Reply-To header
  via mailto: links, try the mailto: link
Be sure your reply has a Subject: header at the top and a blank line before the message body. 
This is an external index of several public inboxes,
see mirroring instructions on how to clone and mirror
all data and code used by this external index.