solo-io / go-utils

golang utilities
Apache License 2.0
110 stars 18 forks source link

New benchmark function #512

Closed marcogschmidt closed 1 year ago

marcogschmidt commented 1 year ago

Summary

This PR adds the Measure function to the benchmarking test utility package. The new function measures the portion of time a given test function spent in user mode, in kernel mode, and in both of them combined. The other functions in the same package have been deprecated and will be removed when other repositories will stop depending on them.

Motivation

The change was prompted by the fact that the current TimeForFuncToComplete function is in some instances reporting execution times of 0 nanoseconds, which causes failures in benchmark tests. I had encountered this problem before and decided to spend some time to investigate it this time around as it seemed to be manifesting itself increasingly often during my refactoring of CI in the ext-auth-service repository.

The issue is caused by the fact that we only measure time spent in user mode and that in some cases a function spends all of its time in kernel mode. An example can be found in this test run, where you can see that the utime (the first field in that poorly logged struct) is the same before and after the execution of the test function, while the stime (second field) goes from 0 to 15875µs:

rusage1: {{0 149100} {0 0} 232368 0 0 0 78 0 0 0 0 0 0 0 15 61}
rusage2: {{0 149100} {0 15875} 232368 0 0 0 97 0 0 0 0 0 0 0 15 62}

I was not able to find out why this is happening in the time I gave myself to look into this. It would be interesting to understand this, but I don't think it is worth the effort at this moment.

Solution

Regardless of the cause of the problem, I think we should take into account both the time we spend in user and kernel modes when benchmarking a function, so I added a new function that returns both of those pieces of information. This way the caller can decide which piece of information they want to use. I still kept a check on zero execution time, but it is run against utime+stime instead of just utime.

As a side note, the new function does not run assertions or write to standard output, I think that should be left to the caller as well.

BOT NOTES: resolves https://github.com/solo-io/go-utils/issues/511

solo-changelog-bot[bot] commented 1 year ago

Issues linked to changelog: https://github.com/solo-io/go-utils/issues/511

nfuden commented 1 year ago

@sam-heilbron as you were looking into benchmarking. @ashishb-solo for visibility as you had previously investigated the 0 count benchmark results