Investigating performance

[googleprojectzero]

Investigating performance

[dms1lva]

Sent you more info via email.

[ifratric]

Hi Dario,
That's indeed strange. 14 module entries per iteration is not a lot and should easily support thousands of iterations/s. With that low performance count, it almost sounds like the target is restarting each iteration. If you're porting from winafl, note that some flag names are slightly different, this could potentially cause the setup not to work properly. Instead of running your target with Jackalope directly, could you run with litecov binary (from TinyInst project) with the same instrumentation flags and paste the output here?

[dms1lva]

I made a mistake and there's actually 124 module entries per iteration :| That could explain the slowdown?

I have confirmed that the target is NOT restarting every iteration, so should be ok on that front.

[ifratric]

Can you paste your command line (feel free to censor anything target-specific)

[dms1lva]

fuzzer.exe -resume -in - -out out -t 500 -instrument_module harness.exe -instrument_module module1.dll -target_module harness.exe -target_method fuzz -nargs 1 -iterations 10000 -persist -loop -- harness.exe @@

[dms1lva]

Still want me to run litecov?

[dms1lva]

When running litecov, I get a bunch of "Target function returned normally". Here is the output when I set the number of iterations to a 100.
litecov.exe -instrument_module harness.exe -instrument_module module1.dll -target_module harness.exe -target_method fuzz-nargs 1 -iterations 100 -persist -coverage_file coverage.txt -loop -- harness.exe @@

Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally
Target function returned normally

[ifratric]

Cool, thanks! I don't see anything out of the ordinary in the command line. Does the performance from litecov match wat you get from fuzzing (at ~10 iterations per second 100 iterations above should take about 10 seconds to complete). Just to make sure it's not a problem on the fuzzer side.

124 entries per iteration would be noticeable, but I'm still thinking even with that the performance drop seems excessive. Can you rerun litecov with -patch_module_entries all and see if

• the target still runs correctly
• what's the number of entries you get with it and
• what's the performance impact

[dms1lva]

I see a big difference when running with litecov. I am testing with 10 000 iterations for both the fuzzer and litecov. I get 870 executions per second with litecov.
I uses this command

Measure-Command {cmd.exe /c ".\litecov.exe -instrument_module harness.exe -instrument_module module1.dll -target_module harness.exe -target_method fuzz -nargs 1 -iterations 10000 -persist -loop -- harness.exe input_1  >run.txt"}

• The target still runs correctly with patch_module_entries
• Only 5 module entries with or without patch_module_entries.
• There is no performance impact.

[dms1lva]

Looking at the jackalope logs, it seems that it doesn't always complete the expected number of iterations. When configuring it to 1000 iterations, I rarely see it do as much. I am using the "process exit" log line to judge when it is restarting the process and I count "persistence method ended" as an iteration.

I am using "trace_debug_events" but I can't see why the process exits. No target crash is logged.

[ifratric]

Ok cool we are getting somewhere! Note that Jackalope sometimes restarts the target for reasons other than crashes and hangs. Specifically, it's going to restart a target when new coverage is detected (in order to make sure new coverage it saw is sample-dependent). This overhead goes away eventually as the corpus becomes more stable over time, but you can still disable this via -clean_target_on_coverage=0.

If that doesn't work, could you paste a section of Jackalope's output.

Above you mentioned "Only 5 module entries". Does this mean you are getting different number of entries when fuzzing vs running under litecov? (This would mean mutated samples are causing additional entries somehow?)

[dms1lva]

Ok I will try with clean_target_on_coverage=0.

Yes I am getting a different number of module entries when fuzzing. While fuzzing, that number is not constant. When fuzzing with winafl, I would get ~80-90% stability. Is that related?

[dms1lva]

With clean_target_on_coverage=0, I always get a 1000 iterations before a process exit so things seem fine on that front.

[ifratric]

Did that help with the performance?

[dms1lva]

Here's the output from a run with clean_target_on_coverage=0
Pretty fast at the beginning but then the speed lowers

Fuzzer version 1.00
Fuzzing sample 00006

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 23680
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 23680

Total execs: 23741
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 61

Total execs: 23801
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 60

Total execs: 23862
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 61

Total execs: 23920
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 58

Total execs: 23978
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 58

Total execs: 24036
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 58

Total execs: 24097
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 61

Total execs: 24155
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7581
Execs/s: 58

Total execs: 24461
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7629
Execs/s: 306

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 24749
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7629
Execs/s: 288

Total execs: 25227
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7629
Execs/s: 478

Total execs: 25670
Unique samples: 25 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7629
Execs/s: 443

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704
Adjusting mutation repeat probability to 0.75

Total execs: 25760
Unique samples: 26 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7654
Execs/s: 90

Total execs: 25885
Unique samples: 28 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7829
Execs/s: 125

Total execs: 26299
Unique samples: 29 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7831
Execs/s: 414

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 26670
Unique samples: 29 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7831
Execs/s: 371

Total execs: 27112
Unique samples: 29 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7831
Execs/s: 442
Adjusting mutation repeat probability to 0.875

Total execs: 27471
Unique samples: 30 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7831
Execs/s: 359
Adjusting mutation repeat probability to 0.857143

Total execs: 27574
Unique samples: 33 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7867
Execs/s: 103

Total execs: 27638
Unique samples: 34 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7867
Execs/s: 64

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 27670
Unique samples: 34 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7867
Execs/s: 32
Adjusting mutation repeat probability to 0.875

Total execs: 27738
Unique samples: 35 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 7874
Execs/s: 68
Adjusting mutation repeat probability to 0.857143

Warning:
Total execs: 27847
Unique samples: 39 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 8059
Execs/s: 109

Total execs: 27870
Unique samples: 40 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14035
Execs/s: 23
Adjusting mutation repeat probability to 0.875

Total execs: 27925
Unique samples: 41 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14051
Execs/s: 55
Adjusting mutation repeat probability to 0.857143

Total execs: 27991
Unique samples: 42 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14051
Execs/s: 66
Adjusting mutation repeat probability to 0.833333
Adjusting mutation repeat probability to 0.875

Total execs: 28067
Unique samples: 44 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14068
Execs/s: 76
Adjusting mutation repeat probability to 0.8

Total execs: 28159
Unique samples: 45 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14901
Execs/s: 92

Total execs: 28384
Unique samples: 47 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14905
Execs/s: 225

Total execs: 28530
Unique samples: 48 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14973
Execs/s: 146

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 28683
Unique samples: 48 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 14973
Execs/s: 153
Adjusting mutation repeat probability to 0.875
Adjusting mutation repeat probability to 0.833333

Total execs: 28755
Unique samples: 51 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15035
Execs/s: 72

Total execs: 28881
Unique samples: 53 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15043
Execs/s: 126
Adjusting mutation repeat probability to 0.888889

Warning:
Total execs: 28917
Unique samples: 54 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15303
Execs/s: 36

Total execs: 28955
Unique samples: 55 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15303
Execs/s: 38

Total execs: 29036
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 81

Total execs: 29067
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29098
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29129
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29157
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Total execs: 29186
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29214
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Total execs: 29243
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29274
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29303
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29333
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29363
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29394
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29424
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29453
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29481
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Total execs: 29509
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Total execs: 29539
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29569
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29599
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29630
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29658
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Warning:
Warning:
Warning: Instrumented module harness.exe, code size: 45056
Instrumented module module1.dll, code size: 26824704

Total execs: 29670
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 12

Total execs: 29682
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 12

Total execs: 29712
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 29743
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29771
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 28

Total execs: 29800
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29829
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 29860
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 31

Total execs: 29890
Unique samples: 56 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30
Fuzzing sample 00056

Total execs: 29942
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 52

Total execs: 29972
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 30001
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 29

Total execs: 30031
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 30061
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 30

Total execs: 30093
Unique samples: 57 (2 discarded)
Crashes: 0 (0 unique)
Hangs: 0
Offsets: 15334
Execs/s: 32

[dms1lva]

When resuming a session, does jackalope need to re-run all the samples first?

[ifratric]

Thanks!

• One unusual thing I see in your log (that I don't know how to explain) is: Normally, Jacakalope runs 1000 mutation iterations (configurable via -iterations_per_round) over a single corpus sample before moving on to another corpus sample. When that happens, you should get a Fuzzing sample <number> message. In your log I only see that message twice, but I see over 5000 execs between them. Normally, changes of fuzzing speed can be related to switching samples to fuzz, as some will be slower than others, but I don't see this happening. The fuzzing loop is in https://github.com/googleprojectzero/Jackalope/blob/main/fuzzer.cpp#L716 and printing that message is in the same function. Did you make any kind of changes to the fuzzing setup or are you using the defaults?

• When the fuzzing speed goes down, could you try to grab a sample from the output directory and run it with litecov to see if you can catch one that also runs slowly there - I'm still trying to figure out if the slowdown is sample/instrumentation-related .

• Jackalope does not re-run the samples when resuming the session. All relevant state gets restored.

[ifratric]

Oh, I guess in your case extra iterations could be caused by the minimizer. Since your samples are pretty large it can take the minimizer some time to handle them (if they can be minimized to a small size). You can disable minimizer via -minimize_samples=0 if you want to play with that.

[ifratric]

One other performance idea - does your harness support sample delivery via shared memory or if it needs to be a file on the disk. See https://github.com/googleprojectzero/Jackalope/blob/main/test.cpp for shared memory target example. I'm wondering if the file IO is to blame to at least some of the performance loss in fuzzing vs litecov.

[dms1lva]

• I did not make any changes to the fuzzing setup.
• Using -minimize_samples=0, I can see the Fuzzing sample <number> message regularly, so your guess was right.
• I took a sample that was running at 1-2 execs/s and ran it in litecov with ~21 execs/s. For every iteration I see 3-6 lines printed with Warning: then nothing after. Like this

Warning:
Warning:
Warning:
Warning:
Warning:
Warning:
Total execs: 905720
Unique samples: 359 (11 discarded)
Crashes: 259 (22 unique)
Hangs: 451
Offsets: 24492
Execs/s: 1

Do you know what could cause this? Is my harness using I/O and slowing down the fuzzing while doing so?

• The harness might support using shared memory, I need to check this out.

[ifratric]

Hmm, strange, I just grepped the Jackalope/TinyInst source and I don't see where the empty warning could come from (there are only several case where there is "Warning" in titlecase, and nowhere is it empty). Is it printed by the harness/target perhaps?

For the sample that runs with ~21 execs/s in litecov,

• What's the speed you get without instrumentation (you can still run it in litecov, just don't specify any -instrument_modules)
• What's the number of module entries per iteration for this sample?
• What is the size of this sample?

[dms1lva]

Yes it is printed by the target. Sorry about that! Does jackalope support an option to suppress the target's output perhaps?

• Without instrumentation I get 81 execs/s
• 202 module entries
• The sample is 58kb

[ifratric]

Output suppression: There's code for it, but it hasn't been enabled/tested properly. But you can try switching https://github.com/googleprojectzero/TinyInst/blob/master/Windows/debugger.cpp#L1829 to true.

Does -patch_module_entries all in litecov help with that particular sample and, if so, what's the speed and number of entries you get after enabling it?

[dms1lva]

Thanks, I'll try that out.

-patch_module_entries all didn't have any significant impact on the speed.

[ifratric]

Hmm if -patch_module_entries (which is meant as a generic solution) has no impact, then I'd have to actually look at the target to see where the overhead comes from (let me know over email/[email protected]/twitter DM if you want to got that route). Or if you want to investigate yourself, you can run your target in the debugger, set breakpoints on the most common entrypoints (as TinyInst gives you their addresses) and see where they are called from.

I suspect low performance is the combination of number of entrypoints and low performance of file IO, but again, without actually looking at target it's difficult to tell and do fixes...