Bug 1853847

(In reply to John Pittman from comment #0)
> Description of problem:
> 
> severe performance degradation when using -s with tree command
> 
> Version-Release number of selected component (if applicable):
> 
> crash-7.2.7-3.el8.x86_64
> 
> How reproducible:
> 
> Every time
> 
> Actual results:
> 
> Command takes an extraordinary amount of time
> 
> Expected results:
> 
> Command should complete in a reasonable amount of time
> 
> Additional info:
> 
> In the vmcore, 'tree -t rbtree -N 0xffff8bb3fb3d4cc0 >/dev/null' takes a
> couple seconds; there are about 55,000 entries.  However, with the addition
> of the -s flag, 'tree -t rbtree -N 0xffff8bb3fb3d4cc0 -s iova.pfn_lo,pfn_hi
> >/dev/null' takes over an hour to complete.
> 
> We created a pykdump script and it completes the same operation in about 4
> seconds, printing identical output.
> 
> def for_all_rbtree(root, sname = None, smember = None):
>     node = rb_first(root)
>     while (node):
>         if (sname):
>             yield  container_of(node, sname, smember)
>         else:
>             yield node
>         node = rb_next(node)
> 
> dma_ops = long(0xffff8c4a78d42000)
> dma = readSU("struct dma_ops_domain", dma_ops)
> iovad = dma.iovad
> for iova in for_all_rbtree(iovad.rbroot, "struct iova", "node"):
>     print("{:#x}".format(iova))
>     print(" pfn_hi =  {}".format(iova.pfn_hi))
>     print(" pfn_lo =  {}".format(iova.pfn_lo))
> 
> crash> epython /home/rdu/jpittman/testscript.py
> 0xffff8bb40296ee80
>  pfn_hi =  7
>  pfn_lo =  4
> 0xffff8bb4685ac6c0
>  pfn_hi =  15
>  pfn_lo =  12
> [....]
> 0xffff8bb451ee3100
>  pfn_hi =  4503599627370479
>  pfn_lo =  4503599627370464
> 0xffff8bb451ee3fc0
>  pfn_hi =  4503599627370495
>  pfn_lo =  4503599627370480
> 0xffff8c4a78d42178
>  pfn_hi =  18446744073709551615
>  pfn_lo =  18446744073709551615
>  ** Execution took   3.87s (real)   3.72s (CPU), Child processes:   0.13s

Hello,

I cannot seem to reproduce this with both 'crash version: 7.2.8-7.el8' and 'crash version: 7.2.7-3.el8' with vmcores obtained on hpe x86_64 and kvm x86_64 machines:

crash> whatis vmap_area_root

crash> p vmap_area_root
vmap_area_root = $1 = {
  rb_node = 0xffff9619a6554d38
}

crash> tree -t rbtree -N 0xffff9619a6554d38 >/dev/null

.. completes in a few seconds ..

crash> tree -t rbtree -N 0xffff9619a6554d38 -s iova.pfn_lo,pfn_hi >/dev/null

.. completes in a few seconds ..


Can you please share the following so that this can be reproduced / fixed?:
1. vmcore file (it's no longer available on 'galvatron' machine)
2. 'home/rdu/jpittman/testscript.py' test script.

If you can attach the same to the BZ, it would really help.

Thanks,
Bhupesh

(In reply to ltao from comment #15)
> Hello,
> 
> I have created a fix, which can shorten the overall run time from 1.5h to
> 40min,

<snip>

> 
> But the fix is only a proof-of-concept, it still takes 40min to finish when
> comparing with
> a few seconds by pykdump script.
> 
> I haven't tried pykdump yet, may need more time to figure out why it takes
> less time. 
> I'm wondering if the current time consuming improvement is acceptable?
> 

This looks like forward progress which is always good!  However, it cannot be evaluated because there is no patch.  Also I doubt that is quite enough performance improvement if pykdump truly only takes only 4 seconds (keep in mind pykdump caches results, so I'm not sure if the 4s was an uncached run or a cached run).

Unless John wants to respond directly since he filed the bug, the best way forward is probably to post to upstream crash-utility list, as a "RFC PATCH 1/1" and ask for feedback, assuming this is still reproducible with upstream crash version?

In addition to patch, probably you will need a "RFC PATCH 0/1" (introduction cover letter to explain "proof of concept" patch, as well as the high-level problem - pykdump difference in performance once that is confirmed).

Hi Dave, Emma, Tao,

Thanks for the response and sorry for the delay.  The improvement is a good one, but I don't think it's drastic enough to be called a fix.  As Dave mentioned, pykdump can cache results, so I did a test to make sure it wasn't.  I edited the script to show the below:

[jpittman@galvatron ~]$ cat /home/rdu/jpittman/testscript.py
from pykdump.API import *
from LinuxDump.trees import *
def for_all_rbtree(root, sname = None, smember = None):
    node = rb_first(root)
    while (node):
        if (sname):
            yield  container_of(node, sname, smember)
        else:
            yield node
        node = rb_next(node)

dma_ops = long(0xffff8c4a78d42000)
dma = readSU("struct dma_ops_domain", dma_ops)
iovad = dma.iovad
for iova in for_all_rbtree(iovad.rbroot, "struct iova", "node"):
    print("{:#x}".format(iova))
    print(" pfn_hi =  {}".format(iova.pfn_hi))
    print(" pfn_lo =  {}".format(iova.pfn_lo))

And ran it as the first command after the vmcore was loaded to make sure it didn't have anything cached yet.

[jpittman@galvatron ~]$ retrace-server-interact 156657913 crash
If you want to execute the command manually, you can run
$ /cores/crashext/gitlab-runner/bin/crash -i /cores/retrace/tasks/156657913/crashrc /cores/retrace/tasks/156657913/crash/vmcore /cores/retrace/repos/kernel/x86_64/usr/lib/debug/lib/modules/3.10.0-1062.18.1.el7.x86_64/vmlinux

....snip

crash> extend /cores/crashext/mpykdumpppc64.so
extend: /cores/crashext/mpykdumpppc64.so: not an ELF format object file
crash> cd /cores/retrace/tasks/156657913/results
Working directory /cores/retrace/tasks/156657913/results.
crash> epython /home/rdu/jpittman/testscript.py | head
0xffff8bb40296ee80
 pfn_hi =  7
 pfn_lo =  4
0xffff8bb4685ac6c0
 pfn_hi =  15
 pfn_lo =  12
0xffff8bb3f7786b00
 pfn_hi =  19
 pfn_lo =  18

....snip

0xffff8bb451ee3100
 pfn_hi =  4503599627370479
 pfn_lo =  4503599627370464
0xffff8bb451ee3fc0
 pfn_hi =  4503599627370495
 pfn_lo =  4503599627370480
0xffff8c4a78d42178
 pfn_hi =  18446744073709551615
 pfn_lo =  18446744073709551615

 ** Execution took   3.13s (real)   3.12s (CPU)

So, we can see it still only took a little over 3 seconds.

Hi Dave, John, Emma,

Thanks so much for the detailed info! I will give it another try and see whether I
can get a better improvement.

Thanks!

Hello,

We can use '-S' instead of '-s' in the crash tree cmd, which can finish in a few seconds and get the identical output as the python script: 

crash> ! date
2021年 08月 04日 星期三 03:57:43 EDT
crash> tree -t rbtree -N 0xffff8bb3fb3d4cc0 -S iova.pfn_lo,pfn_hi > /dev/null
crash> ! date
2021年 08月 04日 星期三 03:57:47 EDT

The difference of -S and -s is, as I quote the man page of crash:

"Similar to -s, but instead of parsing gdb output, member values are read directly from memory."

To illustrate, -s will pass the queries to gdb, in this case, cmds as "output *(struct iova *)0xffff8bb3fb3d4cc0" will be continuously passed to gdb, then gdb will parse the expression according to c language grammer, then evaluate the expression and return it. It is a generic but time-consuming process.

-S will directly read and return the value from memory, without the complex gdb process. If we take an inspection of the python script, it doesn't do the grammer parse neither, just read and return value from memory. At this level, crash and the python script have the same performance.

Any thoughs?

Thanks,
Tao Liu

Hello Dave,

I made another performance test against the gdb-10.2 crash:

[ltao@galvatron ~]$ ./crash-c0e54e9 /cores/retrace/tasks/156657913/crash/vmcore /cores/retrace/repos/kernel/x86_64/usr/lib/debug/lib/modules/3.10.0-1062.18.1.el7.x86_64/vmlinux

crash-c0e54e9> ! date
2021年 08月 05日 星期四 03:25:58 EDT
crash-c0e54e9> tree -t rbtree -N 0xffff8bb3fb3d4cc0 -s iova.pfn_lo,pfn_hi > /dev/null
crash-c0e54e9> ! date
2021年 08月 05日 星期四 04:33:09 EDT    <---- 1h8min

When comparing with the original gdb-7.6 crash of comment15:

crash> !date
2021年 04月 13日 星期二 08:10:12 EDT
crash> tree -t rbtree -N 0xffff8bb3fb3d4cc0 -s iova.pfn_lo,pfn_hi > /dev/null
crash> !date
2021年 04月 13日 星期二 09:44:40 EDT   <---- 1h34min

The performance has improved a little for gdb-10.2

Thanks,
Tao Liu

Thanks Tao! And sorry for the wait. Great find.  In my tests it works very well.  Is there a reason why both -s and -S exists?  Could one be eliminated and only use the process shown in -S?  If no, is it possible to add in the crash man page that -s can be slow?  Thanks again for the great workaround.

Hello John,

There are reasons for -s and -S co-exist. As the "help tree" outputs:

-S struct:  Similar to -s, but instead of parsing gdb output, member values
            are read directly from memory, so the command works much faster
            for 1-, 2-, 4-, and 8-byte members.

the type of iova.pfn_lo,pfn_hi are unsigned long, so -S is more suitable for them. 

-S only works for specific cases. -s is a generic process, works for all cases, but slower.


Thanks,
Tao Liu