CMD API (rz_core_cmd_str) vs Direct API calling

[willgamazo]

hi

When I have the following call sequence:
core = rz_core_new();
RzCoreFile *f = rz_core_file_open(core, path.c_str(), RZ_PERM_R, UT64_MAX);
rz_core_bin_load(core, path.c_str(), UT64_MAX)
rz_core_cmd_str(core, "aaa");
rz_core_cmd_str(core, "s 0xf6e07c15")
rz_core_cmd_str(core, "pdf")

The addr (0xf6e07c15) is a function having a "big" block. When using that sequence of commands the function get disassembled very fast.

However using the API as follows:
RzAnalysisFunction* fcn = rz_analysis_get_function_byname(core->analysis, "fcn.f6e07c15");
rz_core_seek_and_save(core, fcn->addr, true);
PJ *pj = pj_new();
rz_core_print_function_disasm_json(core, fcn, pj);

Results in a significant slower disassembling. Note I'm using "pdf" command.

• The "core" context is the same in both cases.

Do I am missing something?

My original intention was iterate all instructions using the API, but found this case.
I though that was my iteration being slow, but I reproduced the issue calling "rz_core_print_function_disasm_json()" which is basically doing the same.

So, asking here before debugging "rizin" :-)

Also notice the "pdfj" is slower not because is building the JSON, is because the way it is iterating the blocks and the instructions.
The cmd "pdf" is very fast and is calling rz_core_print_disasm() which is a big function, to copy...

However (rz_core_print_function_disasm_json) has a more explicit instruction iteration but very slow:

rz_core_print_function_disasm_json (do the following and is slow):

• Order blocks
• call rz_io_read_at
• call rz_core_print_disasm_json
• iterate rz_pvector_foreach

My question will be what is the faster way to iterate the all blocks->instructions?

Note: I can share the sample privately and testing code if required.

[XVilka]

Have you tried to use something like https://github.com/brendangregg/FlameGraph to see the difference between calls?

[DMaroo]

I suppose the rz_analysis_get_function_byname is causing the extra delay here.

You can find pdf's handler here: https://github.com/rizinorg/rizin/blob/dev/librz/core/cmd/cmd_print.c#L6063
As you can see, the handler uses rz_analysis_get_fcn_in to get the RzAnalysisFunction pointer. I believe it would be relatively faster, the reason being there isn't any searching involved. Even though we use hash tables to search in rz_analysis_get_function_byname as well, but I still believe there is enough overhead to cause a difference.

To test it again, could you instead benchmark the rz_core_cmd_str version with the following snippet?

RzAnalysisFunction *fcn = rz_analysis_get_fcn_in(core->analysis, 0xf6e07c15, RZ_ANALYSIS_FCN_TYPE_ROOT);
rz_core_seek_and_save(core, fcn->addr, true);
PJ *pj = pj_new();
rz_core_print_function_disasm_json(core, fcn, pj);

I believe this should have a similar speed to the cmd_str version.

[willgamazo]

@DMaroo

The delay is not related to (rz_analysis_get_function_byname), there are only 41 functions.
The delay is when calling:
rz_core_print_function_disasm_json(m_core, fcn, pj);

here is the function list:

0xf6e07c15 53 29742 -> 58361 fcn.f6e07c15
0xf7213c4c 3 26 fcn.f7213c4c
0xf7213c18 1 6 fcn.f7213c18
0xf7213d07 1 4 fcn.f7213d07
0xf7213bc8 1 6 fcn.f7213bc8
0xf7213bd8 1 6 fcn.f7213bd8
0xf7213bb8 1 6 fcn.f7213bb8
0xf726e975 1 143 fcn.f726e975
0xf72b5359 9 1359 -> 1363 fcn.f72b5359
0xf72e871e 4 74 -> 92 fcn.f72e871e
0xf73ee172 14 1735 fcn.f73ee172
0xf7404d6c 3 26 fcn.f7404d6c
0xf7404d44 1 6 fcn.f7404d44
0xf7404e25 1 4 fcn.f7404e25
0xf7404cc4 1 6 fcn.f7404cc4
0xf7404d04 1 6 fcn.f7404d04
0xf7404d34 1 6 fcn.f7404d34
0xf7404c24 1 6 fcn.f7404c24
0xf7404c14 1 6 fcn.f7404c14
0xf74276dc 3 26 fcn.f74276dc
0xf74276c0 1 6 fcn.f74276c0
0xf7427795 1 4 fcn.f7427795
0xf7427670 1 6 fcn.f7427670
0xf7427650 1 6 fcn.f7427650
0xf7427640 1 6 fcn.f7427640
0xf7427876 5 138 fcn.f7427876
0xf74276a0 1 6 fcn.f74276a0
0xf742779c 5 218 fcn.f742779c
0xf7427a50 1 53 fcn.f7427a50
0xf7427900 8 336 -> 207 fcn.f7427900
0xf7427a85 8 608 -> 261 fcn.f7427a85
0xf7471e6a 130 95250 -> 95437 fcn.f7471e6a
0xf76e9c60 1 4 fcn.f76e9c60
0xf76e9c64 1 4 fcn.f76e9c64
0xf76e9c70 1 13 fcn.f76e9c70
0xf76e96f0 6 55 fcn.f76e96f0
0xf76e9c5c 1 4 fcn.f76e9c5c
0xf76e9730 12 239 fcn.f76e9730
0xf76e9c58 1 4 fcn.f76e9c58
0xf76eb9b0 101 104026 -> 140881 fcn.f76eb9b0
0xf76eb830 1 4 fcn.f76eb830

[willgamazo]

@DMaroo and @XVilka

Note I updated the original description of the case. To reflect the following:

• "pdfj" is a lot much slower than "pdf"
• "pdfj" is slower because the way of the Iteration. I separated the iteration code with not JSON overhead and is slower.
• The cmd "pdf" is very fast and is calling rz_core_print_disasm() which is a big function, to copy...

My question will be what is the faster way to iterate the all blocks->instructions using the API?
Note: I can share the sample privately and testing code if required.

Extra notes:

More test was done:

Using rizin command line:

aaa
s 0xf6e07c15
pdfj > d.json

That is slow as programmatically. (as showed above.)
But "pdf" is faster. (a lot more faster)

Also notice the "pdfj" is slower not because is building the JSON, is because the way it is iterating the blocks and the instructions.
The cmd "pdf" is very fast and is calling rz_core_print_disasm() which is a big function, to copy...

However (rz_core_print_function_disasm_json) has a more explicit instruction iteration but very slow:

rz_core_print_function_disasm_json (do the following and is slow):

• Order blocks
• call rz_io_read_at
• call rz_core_print_disasm_json
• iterate rz_pvector_foreach

[DMaroo]

My bad, I just realized that you were using "pdf" in your rz_cmd_str. Iteration in JSON building being slow does make sense. Doesn't mean we can't make it faster ;)
Thanks for pointing this out!

[willgamazo]

@DMaroo

What should be the fastest way to iterate all block->instructions in a function?

The way the rz_core_print_function_disasm_json is doing is not feasible for big functions.

However rz_core_print_disasm() is very fast but no API is doing that.

Do I'm missing something?

[XVilka]

It's because pdf is linear, while JSON API (rz_core_print_disasm_json()) isn't. What should be done from our side:

• Rename pdf-like API functions into something clearer, e.g. rz_core_print_disasm_linear()
• Rename rz_core_print_function_disasm_json() into something like rz_core_print_function_disasm_recursive_json()
• Add missing JSON and non-JSON counterparts to both linear and recursive variants
• Add unit/integration tests for these in test/unit/ or test/integration/

[willgamazo]

hi

Including example code. The call to rz_core_analysis_bytes is very slow. That is the reason why rz_core_print_function_disasm_json, is also slow. I'll continue investigating rz_core_analysis_bytes, to see what is slow inside.

Is better way to iterate the instructions than calling rz_core_analysis_bytes to get the vector and the iterate it.?

here is the function and block sizes when it got very slow. (during block: #block# instructions: 14296 block size (read ok): 28602)

function: fcn.f6e07c15, blocks: 53, ninstr: 29128
#block# instructions: 13 block size (read ok): 29
#block# instructions: 21 block size (read ok): 53
#block# instructions: 3 block size (read ok): 6
#block# instructions: 27 block size (read ok): 55
#block# instructions: 7 block size (read ok): 13
#block# instructions: 4 block size (read ok): 8
#block# instructions: 60 block size (read ok): 134
#block# instructions: 67 block size (read ok): 142
#block# instructions: 2 block size (read ok): 4
#block# instructions: 38 block size (read ok): 76
#block# instructions: 2 block size (read ok): 4
#block# instructions: 10 block size (read ok): 25
#block# instructions: 51 block size (read ok): 110
#block# instructions: 2 block size (read ok): 4
#block# instructions: 63 block size (read ok): 140
#block# instructions: 2 block size (read ok): 6
#block# instructions: 1 block size (read ok): 2
#block# instructions: 9 block size (read ok): 18
#block# instructions: 8 block size (read ok): 16
#block# instructions: 17 block size (read ok): 32
#block# instructions: 2 block size (read ok): 3
#block# instructions: 7 block size (read ok): 17
#block# instructions: 2 block size (read ok): 5
#block# instructions: 4 block size (read ok): 13
#block# instructions: 1 block size (read ok): 3
#block# instructions: 6 block size (read ok): 16
#block# instructions: 5 block size (read ok): 12
#block# instructions: 1 block size (read ok): 3
#block# instructions: 4 block size (read ok): 7
#block# instructions: 4 block size (read ok): 9
#block# instructions: 1 block size (read ok): 3
#block# instructions: 1 block size (read ok): 2
#block# instructions: 6 block size (read ok): 10
#block# instructions: 7 block size (read ok): 15
#block# instructions: 2 block size (read ok): 2
#block# instructions: 1 block size (read ok): 2
#block# instructions: 1 block size (read ok): 2
#block# instructions: 1 block size (read ok): 3
#block# instructions: 1 block size (read ok): 2
#block# instructions: 15 block size (read ok): 30
#block# instructions: 6 block size (read ok): 12
#block# instructions: 1 block size (read ok): 2
#block# instructions: 9 block size (read ok): 18
#block# instructions: 5 block size (read ok): 10
#block# instructions: 9 block size (read ok): 18
#block# instructions: 4 block size (read ok): 8
#block# instructions: 7 block size (read ok): 14
#block# instructions: 9 block size (read ok): 18
#block# instructions: 9 block size (read ok): 18
#block# instructions: 14296 block size (read ok): 28602

[willgamazo]

hi
I have more progress, the slow call is: (rz_analysis_mask)
rz_core_analysis_bytes() -->rz_analysis_mask()`

The ironic/fun thing is that ab->mask it is not included in the json output from: rz_core_print_disasm_json
also did not find any usage other than printing that value after assigned to RzAnalysisBytes->mask

[willgamazo]

Update and concluding from my side.

I ended up extracting (copy) from rizin: "rz_core_analysis_bytes". Because of that a couple non-API (IPI) function were extracted:
rz_disasm_check_end
handleMidBB2
handleMidFlags1
rz_core_asm_bb_middle

This allow me:
1- Avoid double instructions iteration (because "rz_core_analysis_bytes" is filling a vector that will be iterated later)
2-Custom decision on what instructions properties to report.

IMO, if rz_analysis_mask get fixed and/or selected to be call by config (in case does not have a bug.), i won't need the copy out of rz_core_analysis_bytes.

Right now I have don't have time to see the issue with rz_analysis_mask. (I suspect there is either a bug or slow implementation)

Thanks.