Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

testing: fuzz execs per second is misleading #48787

Closed
rogpeppe opened this issue Oct 5, 2021 · 4 comments
Closed

testing: fuzz execs per second is misleading #48787

rogpeppe opened this issue Oct 5, 2021 · 4 comments
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support NeedsFix The path to resolution is known, but the work has not been done.
Milestone
Go1.18

Comments

@rogpeppe
Copy link
Contributor

rogpeppe commented Oct 5, 2021 •
edited

commit d55009c

When running the fuzzer, we see output like this (note: we've got a large initial corpus):

fuzz: elapsed: 0s, gathering baseline coverage: 0/29565 completed
fuzz: elapsed: 3s, gathering baseline coverage: 2778/29565 completed
fuzz: elapsed: 6s, gathering baseline coverage: 5567/29565 completed
fuzz: elapsed: 9s, gathering baseline coverage: 8362/29565 completed
fuzz: elapsed: 12s, gathering baseline coverage: 11158/29565 completed
fuzz: elapsed: 15s, gathering baseline coverage: 13987/29565 completed
fuzz: elapsed: 18s, gathering baseline coverage: 16801/29565 completed
fuzz: elapsed: 21s, gathering baseline coverage: 19606/29565 completed
fuzz: elapsed: 24s, gathering baseline coverage: 22432/29565 completed
fuzz: elapsed: 27s, gathering baseline coverage: 25226/29565 completed
fuzz: elapsed: 30s, gathering baseline coverage: 28058/29565 completed
fuzz: elapsed: 32s, gathering baseline coverage: 29565/29565 completed, now fuzzing with 16 workers
fuzz: elapsed: 33s, execs: 181698 (5506/sec), new interesting: 2 (total: 39)
fuzz: elapsed: 36s, execs: 606457 (16844/sec), new interesting: 3 (total: 40)
fuzz: elapsed: 39s, execs: 973060 (24948/sec), new interesting: 5 (total: 42)
fuzz: elapsed: 42s, execs: 1419384 (33792/sec), new interesting: 6 (total: 43)

The "9999/sec" metric is misleading because seems to be an average over the entire time that the fuzzer has spent running, which includes the half a minute that was spent initialising, so even though the actual rate is about 131k execs/sec, the reported rate keeps on rising towards that figure for a long time (it's about right after 15m of running).

I'd suggest that either we start the overall timer for execs/sec when the execs actually start completing, or that it reflect only the rate since the last time the figure was reported.

On balance, I think I'd prefer to see the latter, because that means it's easy to see if things are slowing down (for example by something else interfering with the amount of available CPU time), and that was my intuitive understanding of what the metric was showing me until I realised otherwise.

If you do need to find out the overall rate, it's not hard to do the calculation yourself by dividing total execs by elapsed time.
@mknyszek mknyszek added fuzz Issues related to native fuzzing support NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 5, 2021
@mknyszek mknyszek added this to the Go1.18 milestone Oct 5, 2021
@mknyszek
Copy link
Contributor

mknyszek commented Oct 5, 2021

CC @katiehockman @jayconrod

@katiehockman katiehockman added NeedsFix The path to resolution is known, but the work has not been done. and removed NeedsInvestigation Someone must examine and confirm this is a valid issue and not a duplicate of an existing one. labels Oct 5, 2021
@katiehockman
Copy link
Contributor

katiehockman commented Oct 5, 2021 •
edited

@rogpeppe yep that sounds reasonable. We should fix that. I also think the latter approach of just printing the average since the last reported time is best.

@mvdan
Copy link
Member

mvdan commented Oct 5, 2021

Ooooh, so this explains a lot. I had been wondering why all my fuzz funcs seemed to get decreasingly faster over time :)

@gopherbot
Copy link

Change https://golang.org/cl/354150 mentions this issue: internal/fuzz: log average execs/sec since last log

@golang golang locked and limited conversation to collaborators Oct 6, 2022
Sign up for free to subscribe to this conversation on GitHub. Already have an account? Sign in.
Assignees
No one assigned
Labels
FrozenDueToAge fuzz Issues related to native fuzzing support NeedsFix The path to resolution is known, but the work has not been done.
Projects
Go Security
Status: No status
Milestone
Go1.18
Development

No branches or pull requests
5 participants
@rogpeppe @mknyszek @mvdan @gopherbot @katiehockman