tools/virtiostat: add virtiostat tool

[pizhenwei]

Add a new tool virtiostat to trace VIRTIO devices IO statistics.

Although we have already had iostat(to show block device statistics),
iftop(to show network device statistics), other devices of VIRTIO
family(Ex, console, balloon, GPU and so on) also need tools for each
type. virtiostat works in virtio lower layer, and it could trace all
the devices.

Signed-off-by: zhenwei pi pizhenwei@bytedance.com

[yonghong-song]

[buildbot, test this please]

[pizhenwei]

[buildbot, test this please]

@yonghong-song
Hi, testbot reports an error on ubuntu1710 (and only on ubuntu1710)

8: FAIL: test_jumps (__main__.TestBPFSocket)
8: ----------------------------------------------------------------------
8: Traceback (most recent call last):
8:   File "/home/iovisor/jenkins/workspace/bcc-pr/label/ubuntu1710/tests/python/test_call1.py", line 43, in test_jumps
8:     self.assertGreater(self.stats[c_int(S_IP)].value, 0)
8: AssertionError: 0L not greater than 0

I tried to build ubuntu-1710 environment to reproduce this issue, but apt source has been broken. Could you give me a hint why this test fails?

[yonghong-song]

I could be a timing issue. networking packet did not go through yet and then socket is closed. Let me try again. It should not be related to your patch.

[yonghong-song]

[buildbot, test this please]

[yonghong-song]

Some comments where these constants come from?

[yonghong-song]

No need in four different lines for parameters, you have two lines with each line two parameters.

[yonghong-song]

extra line is not needed.

[yonghong-song]

no need one parameter per line.

[yonghong-song]

why you need the above two lines to get _out_sgs and _in_sgs? They are in argument list and you should be able to use out_sgs and in_sgs directly?

[yonghong-song]

no need for extra line

[yonghong-song]

long line, break into two lines?

[yonghong-song]

break into two lines?

[yonghong-song]

Let us ensure default output has at most 80 char's per line. Here we exceeded it.

[yonghong-song]

Maybe you can give more explanation why these statistics are useful to find/debug a real issue. Real use case justification is needed to be included in bcc tools.

[pizhenwei]

@yonghong-song
Refine codes/docs as you suggested except

    unsigned int _out_sgs = PT_REGS_PARM3(ctx);
    unsigned int _in_sgs = PT_REGS_PARM4(ctx);

Add some comments in code, and I'm not sure if I hit a bug....
Two cases I have tested:
1, get out_sgs from args and PT_REGS_PARMx, and generate perf event. there is a probability that getting different value.
2, building a kmod and also get different value.

#include <linux/kernel.h>
#include <linux/module.h>
#include <linux/kprobes.h>
#include <linux/uaccess.h>
#include <linux/scatterlist.h>

static int kp_virtqueue_add_sgs_handler(struct kprobe *p, struct pt_regs *regs)
{
	struct scatterlist *sg = (struct scatterlist *)regs->si;
	int out = (int)regs->dx;
	int in = (int)regs->cx;

	printk("sg %p, out %d, in %d\n", sg, out, in);

	return 0;
}

static struct kprobe kp = {
	.symbol_name	= "virtqueue_add_sgs",
	.pre_handler = kp_virtqueue_add_sgs_handler,
};

static int __init kprobe_init(void)
{
	int ret;

	ret = register_kprobe(&kp);
	if (ret < 0) {
		pr_err("register_kprobe failed, returned %d\n", ret);
		return ret;
	}

	pr_info("[probe-unlink]Planted kprobe at %p\n", kp.addr);
	return 0;
}

static void __exit kprobe_exit(void)
{
	unregister_kprobe(&kp);
	pr_info("[probe-unregistered]kprobe at %p unregistered\n", kp.addr);
}

module_init(kprobe_init)
module_exit(kprobe_exit)
MODULE_LICENSE("GPL");
MODULE_AUTHOR("pizhenwei pizhenwei@bytedance.com");

[yonghong-song]

@pizhenwei thanks for reporting. Indeed, the incorrect param value is caused by a bug in bcc rewriter. I have just put a fix #3275.

When I try to run, I hit the following verifier bug:

-bash-4.4$ sudo ./virtiostat.py 
bpf: Argument list too long. Program  too large (402 insns), at most 4096 insns

Traceback (most recent call last):
  File "./virtiostat.py", line 184, in <module>
    b.attach_kprobe(event="virtqueue_add_sgs", fn_name="trace_virtqueue_add_sgs")
  File "/usr/lib/python2.7/site-packages/bcc/__init__.py", line 679, in attach_kprobe
    fn = self.load_func(fn_name, BPF.KPROBE)
  File "/usr/lib/python2.7/site-packages/bcc/__init__.py", line 412, in load_func
    (func_name, errstr))
Exception: Failed to load BPF program trace_virtqueue_add_sgs: Argument list too long
-bash-4.4$

I am using llvm12 and llvm13(trunk) and both have issues. Let me dig more on this. I suspect this is related to the following code

    for (i = 0; (i < VIRTIO_MAX_SGS) && (i < num); i++) {
        for (n = 0, sgp = sgs[i]; sgp && (n < SG_MAX); sgp = __sg_next(sgp)) {
            length += sgp->length;
            n++;
        }
    }

where verifier might not handle effectively.

[yonghong-song]

I did some analysis on verifier failure. The reason is due to the following code:

; for (i = 0; (i < VIRTIO_MAX_SGS) && (i < num); i++) { // Line  60
  90:   15 08 15 00 00 00 00 00 if r8 == 0 goto +21
  91:   bf 81 00 00 00 00 00 00 r1 = r8
  92:   07 01 00 00 ff ff ff ff r1 += -1
  93:   67 01 00 00 20 00 00 00 r1 <<= 32
  94:   77 01 00 00 20 00 00 00 r1 >>= 32
  95:   b7 02 00 00 05 00 00 00 r2 = 5
  96:   2d 12 01 00 00 00 00 00 if r2 > r1 goto +1
  97:   b7 08 00 00 06 00 00 00 r8 = 6
  98:   b7 02 00 00 00 00 00 00 r2 = 0
  99:   b7 09 00 00 00 00 00 00 r9 = 0
 100:   7b 8a 68 ff 00 00 00 00 *(u64 *)(r10 - 152) = r8
 101:   05 00 35 00 00 00 00 00 goto +53

Insn 100 saves r8, but r8 has conservative value at insn 91 (suppose insn 96 evaluates true) compared to r1. Such a conservative value will make verifier think the loop can execute up to u64_max which will cause verification failure.

We do have a pass in llvm12/13 intended to prevent such optimization. I will study more with llvm on how to prevent this transformation. Looks like you are using an early version of llvm which didn't do the above transformation..

[brendangregg]

Cool tool, thanks!

The man page is missing a description of the columns.

A later addition could be a -x mode for extended stats, to include average latency (similar to iostat).

[pizhenwei]

I did some analysis on verifier failure. The reason is due to the following code:

; for (i = 0; (i < VIRTIO_MAX_SGS) && (i < num); i++) { // Line  60
  90:   15 08 15 00 00 00 00 00 if r8 == 0 goto +21
  91:   bf 81 00 00 00 00 00 00 r1 = r8
  92:   07 01 00 00 ff ff ff ff r1 += -1
  93:   67 01 00 00 20 00 00 00 r1 <<= 32
  94:   77 01 00 00 20 00 00 00 r1 >>= 32
  95:   b7 02 00 00 05 00 00 00 r2 = 5
  96:   2d 12 01 00 00 00 00 00 if r2 > r1 goto +1
  97:   b7 08 00 00 06 00 00 00 r8 = 6
  98:   b7 02 00 00 00 00 00 00 r2 = 0
  99:   b7 09 00 00 00 00 00 00 r9 = 0
 100:   7b 8a 68 ff 00 00 00 00 *(u64 *)(r10 - 152) = r8
 101:   05 00 35 00 00 00 00 00 goto +53

Insn 100 saves r8, but r8 has conservative value at insn 91 (suppose insn 96 evaluates true) compared to r1. Such a conservative value will make verifier think the loop can execute up to u64_max which will cause verification failure.

We do have a pass in llvm12/13 intended to prevent such optimization. I will study more with llvm on how to prevent this transformation. Looks like you are using an early version of llvm which didn't do the above transformation..

I tested this on llvm-3.8, it worked fine. And tested on llvm-12, also reproduced this verification failure.

[yonghong-song]

please change _vq to vq, so argument, so it can be consistent with rest of arguments.

[yonghong-song]

_vq => vq

[yonghong-song]

Please remove the above comment. This commit will be merged on top of the above commit, so no need to mention that.

[yonghong-song]

@pizhenwei please also incorporate the following changes in your next revision. llvm and kernel work to address these issues are ongoing. Thanks!

diff --git a/tools/virtiostat.py b/tools/virtiostat.py
index a6a38bd1..1b5fbccf 100755
--- a/tools/virtiostat.py
+++ b/tools/virtiostat.py
@@ -95,6 +95,28 @@ static u64 count_len(struct scatterlist **sgs, unsigned int num)
             length += sgp->length;
             n++;
         }
+
+        /* IndVarSimplifyPass with clang 12 may cause verifier failure:
+         *   ; for (i = 0; (i < VIRTIO_MAX_SGS) && (i < num); i++) { // Line  60
+         *   90:   15 08 15 00 00 00 00 00 if r8 == 0 goto +21
+         *   91:   bf 81 00 00 00 00 00 00 r1 = r8
+         *   92:   07 01 00 00 ff ff ff ff r1 += -1
+         *   93:   67 01 00 00 20 00 00 00 r1 <<= 32
+         *   94:   77 01 00 00 20 00 00 00 r1 >>= 32
+         *   95:   b7 02 00 00 05 00 00 00 r2 = 5
+         *   96:   2d 12 01 00 00 00 00 00 if r2 > r1 goto +1
+         *   97:   b7 08 00 00 06 00 00 00 r8 = 6
+         *   98:   b7 02 00 00 00 00 00 00 r2 = 0
+         *   99:   b7 09 00 00 00 00 00 00 r9 = 0
+         *  100:   7b 8a 68 ff 00 00 00 00 *(u64 *)(r10 - 152) = r8
+         *  101:   05 00 35 00 00 00 00 00 goto +53
+         * Note that r1 is refined by r8 is saved to stack for later use.
+         * This will give verifier u64_max loop bound and eventually cause
+         * verification failure. Workaround with the below asm code.
+         */
+#if __clang_major__ >= 7
+        asm volatile("" : "=r"(i) : "0"(i));
+#endif
     }
 
     return length;
@@ -107,6 +129,13 @@ static void record(struct virtqueue *vq, struct scatterlist **sgs,
     virtio_stat_t *vs;
     u64 key = (u64)vq;
+    /* Workaround: separate two count_len() calls, one here and the
+     * other below. Otherwise, compiler may generate some spills which
+     * harms verifier pruning. This happens in llvm12, but not llvm4.
+     * Below code works on both cases.
+     */
+    u64 in_bw = count_len(sgs, in_sgs);
+
     vs = stats.lookup(&key);
     if (!vs) {
         bpf_probe_read_kernel(newvs.driver, sizeof(newvs.driver), vq->vdev->dev.driver->name);
@@ -114,13 +143,13 @@ static void record(struct virtqueue *vq, struct scatterlist **sgs,
         bpf_probe_read_kernel(newvs.vqname, sizeof(newvs.vqname), vq->name);
         newvs.in_sgs = in_sgs;
         newvs.out_sgs = out_sgs;
-        newvs.in_bw = count_len(sgs, in_sgs);
+        newvs.in_bw = in_bw;
         newvs.out_bw = count_len(sgs, out_sgs);
         stats.update(&key, &newvs);
     } else {
         vs->in_sgs += in_sgs;
         vs->out_sgs += out_sgs;
-        vs->in_bw += count_len(sgs, in_sgs);
+        vs->in_bw += in_bw;
         vs->out_bw += count_len(sgs, out_sgs);
     }
 }

[yonghong-song]

[buildbot, ok to test]

[yonghong-song]

Please consider to address the following comments from @brendangregg

• The man page is missing a description of the columns.
• A later addition could be a -x mode for extended stats, to include average latency (similar to iostat).

[brendangregg]

I tried using it, and as an iostat-like tool I found the options weren't what I expected. Instead of:

virtiostat
virtiostat -i 2
virtiostat -i 2 -d 10

I'd consider:

virtiostat
virtiostat 2
virtiostat 2 5

ie

virtiostat [interval [count]]

for consistency with the other stat tools.

Generally I'd reserve the tool arguments for the most common use case, and then options (like -T) for everything else. That saves typing. I think the most common use case here would be setting the interval and count, so we can drop the -i and -d. (note that this switches a duration to a count.)

[pizhenwei]

I tried using it, and as an iostat-like tool I found the options weren't what I expected. Instead of:

virtiostat
virtiostat -i 2
virtiostat -i 2 -d 10

I'd consider:

virtiostat
virtiostat 2
virtiostat 2 5

ie

virtiostat [interval [count]]

for consistency with the other stat tools.

Generally I'd reserve the tool arguments for the most common use case, and then options (like -T) for everything else. That saves typing. I think the most common use case here would be setting the interval and count, so we can drop the -i and -d. (note that this switches a duration to a count.)

I ran grep "parser.add_argument" *.py | grep grep -E "interval|duration" in tools directory, and noticed that a lot of tools use -i/-d.
Making virtiostat look like iostat may break the hobby of the bcc tools.

[pizhenwei]

Please consider to address the following comments from @brendangregg

• The man page is missing a description of the columns.

Add some comment in description about SGs and BW.

• A later addition could be a -x mode for extended stats, to include average latency (similar to iostat).

Let's make sure the basic version work fine firstly. To implement -x mode needs record the request starting time and done time (to track another function). So in my plan, I'd like to implement this in another PR.

[yonghong-song]

The above code failed with llvm12 in my environment. Could you try my original suggestion in your environment?
if it works, let us use that. We can revisit once we got some fix in llvm or verifier.

Also, it looks count_len for in_bw is different from previous version. I checked the kernel source code. This version seems correct.

[pizhenwei]

The above code failed with llvm12 in my environment. Could you try my original suggestion in your environment?
if it works, let us use that. We can revisit once we got some fix in llvm or verifier.

I tested this with LLVM version 12.0.0, it worked fine .... But I still modify it as your suggestion.

LLVM (http://llvm.org/):
  LLVM version 12.0.0
  
  Optimized build.
  Default target: x86_64-pc-linux-gnu
  Host CPU: skylake

Also, it looks count_len for in_bw is different from previous version. I checked the kernel source code. This version seems correct.

Yes, this version is correct.

[brendangregg]

I ran grep "parser.add_argument" *.py | grep grep -E "interval|duration" in tools directory, and noticed that a lot of tools use -i/-d.
Making virtiostat look like iostat may break the hobby of the bcc tools.

From https://github.com/iovisor/bcc/blob/master/CONTRIBUTING-SCRIPTS.md:

Consider command line options. Should it have -p for filtering on a PID? -T for timestamps? -i for interval? See other tools for examples, and copy the style: the usage message should list example usage at the end. Remember to keep the tool doing one thing and doing it well. Also, if there's one option that seems to be the common case, perhaps it should just be the first argument and not need a switch (no -X). A special case of this is *stat tools, like iostat/vmstat/etc, where the convention is [interval [count]].

Other tools use -i -d when there is a different common case. E.g., funccount(8), where the common case is the function you want to trace, leaving interval/duration for the -i -d switches.

[brendangregg]

BTW, command line tools, on both Unix and Windows, frequently use this convention. For example, this is not their usage:

ls -l -file myfile.txt
cd -d c:\Windows

They have dropped the switch for the common case.

[pizhenwei]

I ran grep "parser.add_argument" *.py | grep grep -E "interval|duration" in tools directory, and noticed that a lot of tools use -i/-d.
Making virtiostat look like iostat may break the hobby of the bcc tools.

From https://github.com/iovisor/bcc/blob/master/CONTRIBUTING-SCRIPTS.md:

Consider command line options. Should it have -p for filtering on a PID? -T for timestamps? -i for interval? See other tools for examples, and copy the style: the usage message should list example usage at the end. Remember to keep the tool doing one thing and doing it well. Also, if there's one option that seems to be the common case, perhaps it should just be the first argument and not need a switch (no -X). A special case of this is *stat tools, like iostat/vmstat/etc, where the convention is [interval [count]].

Other tools use -i -d when there is a different common case. E.g., funccount(8), where the common case is the function you want to trace, leaving interval/duration for the -i -d switches.

Force pushed as you suggested. Thanks a lot.

usage: virtiostat.py [-h] [-T] [-D] [interval] [count]

[yonghong-song]

LGTM. Thanks!

[brendangregg]

Thanks!