-
Notifications
You must be signed in to change notification settings - Fork 7.7k
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
fortio: optimized http client, simplified logging #470
Conversation
- build and use fortio in perf/standalone scripts - (win) fix for having more connections than requested
Also changing threshold for sleep time histogram to 5%
Now getting exactly the expected number of sockets But performance is still significantly lower than wrk
On my Mac: Old net/http : 19.7k qps with 2 threads (-http -1) New -http 1 : 30.5k ops with 2 threads And 1/8th of the user cpu Interface to select between the 2 clients Wip because it doesn’t work for chunked yet only for fixed Content-Length (like echosrv)
on the benchmark boxes: fortio with new http client:
wrk:
new profile:
|
devel/fortio/http.go
Outdated
|
||
const toLowerMask byte = ('a' - 'A') | ||
|
||
// ASCIIFold returns a byte array equal to the input string but in lowercase. |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
any reason to not use something like: byte[](strings.ToLower(str))
?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
yes it's slower/doing unicode correctness (will add a benchmark) and tests the folding. though for since function might be simpler
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
also thanks for having looked but this one is still wip, #460 is ready though!
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
BenchmarkASCIIFoldNormalToLower-8 3000000 415 ns/op 96 B/op 3 allocs/op
BenchmarkASCIIFoldCustomToLowerMap-8 5000000 362 ns/op 96 B/op 3 allocs/op
BenchmarkASCIIFold-8 10000000 116 ns/op 32 B/op 1 allocs/op
So it's 3.5x faster and 1/3rd of memory (this being said it doesn't matter too much given the absolute numbers) - I'm also changing the code to upper case to not mangle \r\n etc
Folding is 4x faster than built in, 1/3rd of allocs Search is 10x faster, no alloc instead of a lot ``` BenchmarkASCIIFoldNormalToLower-8 3000000 416 ns/op 96 B/op 3 allocs/op BenchmarkASCIIFoldCustomToLowerMap-8 5000000 371 ns/op 96 B/op 3 allocs/op BenchmarkASCIIToUpper-8 20000000 104 ns/op 32 B/op 1 allocs/op BenchmarkFoldFind0-8 200000 7621 ns/op 2112 B/op 3 allocs/op BenchmarkFoldFind-8 2000000 669 ns/op 0 B/op 0 allocs/op ```
unit test for parsing, reads the first chunk
The granularity seems not great no ?
- added some doc in WORKSPACE about wool - initial support for fasthttp
devel/fortio/README.md
Outdated
Enable http compression | ||
-gomaxprocs int | ||
Setting for runtime.GOMAXPROCS, <1 doesn't change the default | ||
-http int |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
a small nit: I'd prefer if this were not integer values.
something like:
--http
--fast_http1
--fast_http1.1
--fast_http1.1_no_keep_alive
where it defaults to --http
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
changing/splitting flags
devel/fortio/cmd/echosrv/echo.go
Outdated
"net/http" | ||
"sync/atomic" | ||
|
||
"github.com/golang/glog" | ||
log "istio.io/istio/devel/fortio" |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
do we need/want this alias? any harm in just having the calls be fortio.LogV()
and fortio.DbgOn()
?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
log.DbgOn() was shorter and clearer that it's about logging (I guess this stems from the fact that in theory it should be it's own package - or better, not reinvented - but fortio is sort of a bundle of features that can be used as a whole or piecemeal)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
my objection, if you will, here is that you are aliasing a package (that you control) for no reason other than to shorten it and, as a result, we end up with a bit of stutter (log.LogV()
).
it would be nice if it were a distinct package, but I don't know that it is required.
I notice elsewhere that we don't have the same alias. If anything, I would suggest a consistent approach.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
k changing
devel/fortio/cmd/fortio/main.go
Outdated
@@ -87,13 +83,12 @@ func main() { | |||
compressionFlag = flag.Bool("compression", false, "Enable http compression") | |||
goMaxProcsFlag = flag.Int("gomaxprocs", 0, "Setting for runtime.GOMAXPROCS, <1 doesn't change the default") | |||
profileFlag = flag.String("profile", "", "write .cpu and .mem profiles to file") | |||
headersFlags flagList | |||
httpClient = flag.Int("http", 1, |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
i commented on this above, but some more food for thought: generally, for api design, we start with 0 as the default and move up. So, I wouldn't expect -1
to be a valid value here.
Something like the following is more what I would expect:
enum HttpClient {
HTTP_CLIENT_UNSPECIFIED = 0;
FAST_1_0 = 1;
FAST_1_1 = 2;
FAST_1_1_NO_KEEP_ALIVE = 3;
}
in go, this might be:
type HttpClient int
const (
Standard HttpClient = iota
Fast
Fast11
Fast11NoKeepAlive
)
to use in a flag, you might have to make HttpClient
implement flag.Value
for this approach however.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
this one is only in the main, so it's not really an api design but just how to expediently select which client and option to use, I do agree strings would be cleaner and an auto mapping from string<->enum like I implemented in logger.go is nicer but it's also quite a lot more code - I will make some change, thanks!
devel/fortio/http.go
Outdated
// Host is treated specially, remember that one separately. | ||
hostOverride string | ||
// Buffer size for optimized client | ||
bufferSizeKbFlag = flag.Int("httpbufferkb", 32, "Size of the buffer (max data size) for the optimized http client in kbytes") |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
typically, flags are placed in the main code, and not in the library code. any reason to have them here instead?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
it's sort of a constant, but configurable, but I can move it in the constructor but it'll more more hassles to transmit it
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Another option: export the var, and in the cmd, use something like flag.IntVar
to reference the variable.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ok: I moved those 2 flags (in theory I should change the error messages which also assumed the fix was under -httpbufferkb)
devel/fortio/http.go
Outdated
bc.req = append(bc.req, []byte("Connection: close\r\n")...) | ||
} | ||
} | ||
for h := range extraHeaders { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
did you look at bytes.Buffer
for usage here? Instead of all the casting and appends, etc., you could have buf.Write()
and buf.WriteString()
calls ?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
thx ! I'll change and remove the // TODO: ugly ... what's a good/elegant and efficient way to do this
devel/fortio/logger.go
Outdated
} | ||
|
||
// LogOn returns true if a given level is currently logged. | ||
func LogOn(lvl LogLevel) bool { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: i'd just call this LogEnabled
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
my first version was IsLogEnabled() and IsLoggingDebug() but I tried to go "go way" (shortest readable)
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
So, we definitely don't want the Is
prefix. I don't personally like On
, but I won't object if that is your preference.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
👍 I do prefer Enabled but it's long and feels unnatural in go
devel/fortio/logger.go
Outdated
|
||
// Log at the given level. | ||
// 2 level of calls so it's always same depth for extracting caller file/line | ||
func Log(lvl LogLevel, format string, rest ...interface{}) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
if this takes a format string, would it be more appropriate to call it Logf
?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
last PR you made me remove the F in my Print - and I agreed it was nicer :-)
but the main reason I'm trying to make the Api as short yet meaningful
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
I fully reserve the right to disagree with myself ;).
I don't remember the prior context, but just suggesting that appending f
might make it clearer that there is formatting happening. Up to you.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
ok I'm adding the "f" as that solves my variable vs function namespace conflict issue - thx!
devel/fortio/logger.go
Outdated
// -- would be nice to be able to create those in a loop instead of copypasta: | ||
|
||
// Dbg logs if Debug level is on. | ||
func Dbg(format string, rest ...interface{}) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
nit: expand to Debugf
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
can I keep Dbg :-) ?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Sure. I'm not going to block the PR over it, but I think Dbg
might be a bit too short (and harder to guess for non-ldemailly users of the API). Debugf
is easier to anticipate.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
changed !
also thanks to adding the f I changed the bool LogOn() -> Log() and
DebugOn() -> LogDebug()
if LogDebug() {
flows nicely
devel/fortio/logger.go
Outdated
} | ||
|
||
// Info logs if Info level is on. | ||
func Info(format string, rest ...interface{}) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
here and elsewhere, if format strings are taken, it seems like using Infof
might be clearer.
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
only weird one now is LogVf() is quite a mouthful
devel/fortio/logger.go
Outdated
} | ||
|
||
// DbgOn is a shortcut for LogOn(D). | ||
func DbgOn() bool { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
again, small issue, but I prefer DebugEnabled
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
LogDebug
Wasn’t working with last chunk (0\r\n\r\n) being in a separate frame
Thanks a lot for all the notes. I made inline replies and changes PTAL! |
devel/fortio/logger.go
Outdated
} | ||
|
||
// VOn is a shortcut for LogOn(V). | ||
func VOn() bool { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
here, you might consider just V()
. that would more closely align with glog
and expectations (though it notably does not take an arg).
however, i'm a bit worried about the difference in VOn()
and DbgOn()
. It feels like it should either be VOn()
and DOn()
or VerboseOn()
and DebugOn
(if we go with fuller const names).
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
it's DbgOn()
because the logging shortcut is Dbg()
V()
was a bit short for a function and Verbose()
a bit long and Verb()
or Vrb()
not clear or misleading so I called the shortcut for V level logging LogV()
so I guess this should in theory be LogVOn() or IsLoggingV()... not sure... naming is hard :-) suggestions welcome
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
changed !
Maybe this was answered elsewhere, but what is the rationale for creating a new logging package vs. using an existing one, e.g. glog? |
thx doug!
A combination of things but in truth none great
|
Does this set a precedent for other contributors re: NIH?
glog doesn't have any non-stdlib dependencies and I suspect most of its stdlib dependencies are used elsewhere in any common golang program. Dependencies aren't necessarily a bad thing, particularly if they are from stdlib or another well-tested package.
IMO the more named log levels, the less semantically meaningful they become. WARNING/ERROR/FATAL seems sufficient for non-info/debug related logs, e.g. WARNING = "might be bad", ERROR = "definitely bad but we can recover", FATAL = "bad+panic". I'm not sure where CRITICAL fits into that picture.
Agreed on this point though the default flag value can be overridden per binary with a one line change, e.g. func main() {
flag.Lookup("logtostderr").Value.Set("true") // change default logging behavior
flag.Parse()
glog.Info("Hello, world")
}
This seems like an argument against writing another logging package re: users familiarity with existing API/names :) |
@@ -155,7 +155,7 @@ func (p *promProxy) Teardown() (err error) { | |||
if p.portFwdProcess != nil { | |||
err := p.portFwdProcess.Kill() | |||
if err != nil { | |||
glog.Error("Failed to kill port-forward process, pid: %s", p.portFwdProcess.Pid) | |||
glog.Errorf("Failed to kill port-forward process, pid: %d", p.portFwdProcess.Pid) |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
2 bugs here found by linter, not sure how come it wasn't found by presubmit
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
Looks pretty good to me. Thanks for your patience on my nits. The only thing I see that you may or may not care about are places where Log(Debug) could be written as LogDebug().
if percentNegative > 5 { | ||
sleepTime.Print(os.Stdout, "Aggregated Sleep Time", 50) | ||
fmt.Printf("WARNING %.2f%% of sleep were falling behind\n", percentNegative) | ||
} else { | ||
if Verbosity > 0 { | ||
if Log(Verbose) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
could be LogVerbose()
right?
funcTimes.Log(tIDStr+" Function duration", 99) | ||
if verbosity > 2 { | ||
if Log(Debug) { |
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
here and elsewhere, could we use the LogDebug()
helper method you added?
There was a problem hiding this comment.
Choose a reason for hiding this comment
The reason will be displayed to describe this comment to others. Learn more.
in some intermediate version I had completely deleted the shortcuts as Log(Verbose) is as short and clear (and more generic) as LogVerbose() until I got to the main packages where there one need to use fortio.Verbose, so I put them back but only for outside
thanks a lot for your time and your patience continuing my go education ! |
* fortio update - build and use fortio in perf/standalone scripts - fix for having more connections than requested * Updating sample to test using echosrv (slightly lower latency) Also changing threshold for sleep time histogram to 5% * Adding -gomaxprocs flag * One client per goroutine Now getting exactly the expected number of sockets But performance is still significantly lower than wrk * Adding profiler option * Homegrown http client On my Mac: Old net/http : 19.7k qps with 2 threads (-http -1) New -http 1 : 30.5k ops with 2 threads And 1/8th of the user cpu Interface to select between the 2 clients * More comments and backtrack test * http_test was missing from bazel ran gazelle * Added benchmark and fix folding bugs Folding is 4x faster than built in, 1/3rd of allocs Search is 10x faster, no alloc instead of a lot ``` BenchmarkASCIIFoldNormalToLower-8 3000000 416 ns/op 96 B/op 3 allocs/op BenchmarkASCIIFoldCustomToLowerMap-8 5000000 371 ns/op 96 B/op 3 allocs/op BenchmarkASCIIToUpper-8 20000000 104 ns/op 32 B/op 1 allocs/op BenchmarkFoldFind0-8 200000 7621 ns/op 2112 B/op 3 allocs/op BenchmarkFoldFind-8 2000000 669 ns/op 0 B/op 0 allocs/op ``` * chunked decoding unit test for parsing, reads the first chunk * fasthttp client wrapper (-http 3) - added some doc in WORKSPACE about wtool - initial support for fasthttp * Make linter happy though I might drop fasthttp as it’s not faster (but it’s more complete) and adds a lot of dependencies * Split connect out * Fixing merge error * adding fortio Logger * Fixing bazel build And misc comment/leftover from #460 etc * Shorter logger names * Switched to new logging * Eradicate Verbosity leftovers * Added -logprefix and -logcaller; Refactor start on http.go also fixed a couple of calls missing % codes * Minor edits, saving to GitHub wip * Woot http1.1 works now Still unwieldy but working ! * Some profiler optimizations * More profiler opt * Make lint happy by making checking connection closed header a flag * Dropping fasthttp dependency * Moved 3 changes to #495 * Minor: use version in echoers, use 3 digits * Code review updates (thx doug!) + serious chunked bug fix Wasn’t working with last chunk (0\r\n\r\n) being in a separate frame * Code review comment thx doug! Former-commit-id: e09dcaf
* fortio update - build and use fortio in perf/standalone scripts - fix for having more connections than requested * Updating sample to test using echosrv (slightly lower latency) Also changing threshold for sleep time histogram to 5% * Adding -gomaxprocs flag * One client per goroutine Now getting exactly the expected number of sockets But performance is still significantly lower than wrk * Adding profiler option * Homegrown http client On my Mac: Old net/http : 19.7k qps with 2 threads (-http -1) New -http 1 : 30.5k ops with 2 threads And 1/8th of the user cpu Interface to select between the 2 clients * More comments and backtrack test * http_test was missing from bazel ran gazelle * Added benchmark and fix folding bugs Folding is 4x faster than built in, 1/3rd of allocs Search is 10x faster, no alloc instead of a lot ``` BenchmarkASCIIFoldNormalToLower-8 3000000 416 ns/op 96 B/op 3 allocs/op BenchmarkASCIIFoldCustomToLowerMap-8 5000000 371 ns/op 96 B/op 3 allocs/op BenchmarkASCIIToUpper-8 20000000 104 ns/op 32 B/op 1 allocs/op BenchmarkFoldFind0-8 200000 7621 ns/op 2112 B/op 3 allocs/op BenchmarkFoldFind-8 2000000 669 ns/op 0 B/op 0 allocs/op ``` * chunked decoding unit test for parsing, reads the first chunk * fasthttp client wrapper (-http 3) - added some doc in WORKSPACE about wtool - initial support for fasthttp * Make linter happy though I might drop fasthttp as it’s not faster (but it’s more complete) and adds a lot of dependencies * Split connect out * Fixing merge error * adding fortio Logger * Fixing bazel build And misc comment/leftover from istio#460 etc * Shorter logger names * Switched to new logging * Eradicate Verbosity leftovers * Added -logprefix and -logcaller; Refactor start on http.go also fixed a couple of calls missing % codes * Minor edits, saving to GitHub wip * Woot http1.1 works now Still unwieldy but working ! * Some profiler optimizations * More profiler opt * Make lint happy by making checking connection closed header a flag * Dropping fasthttp dependency * Moved 3 changes to istio#495 * Minor: use version in echoers, use 3 digits * Code review updates (thx doug!) + serious chunked bug fix Wasn’t working with last chunk (0\r\n\r\n) being in a separate frame * Code review comment thx doug! Former-commit-id: e09dcaf
* fortio update - build and use fortio in perf/standalone scripts - fix for having more connections than requested * Updating sample to test using echosrv (slightly lower latency) Also changing threshold for sleep time histogram to 5% * Adding -gomaxprocs flag * One client per goroutine Now getting exactly the expected number of sockets But performance is still significantly lower than wrk * Adding profiler option * Homegrown http client On my Mac: Old net/http : 19.7k qps with 2 threads (-http -1) New -http 1 : 30.5k ops with 2 threads And 1/8th of the user cpu Interface to select between the 2 clients * More comments and backtrack test * http_test was missing from bazel ran gazelle * Added benchmark and fix folding bugs Folding is 4x faster than built in, 1/3rd of allocs Search is 10x faster, no alloc instead of a lot ``` BenchmarkASCIIFoldNormalToLower-8 3000000 416 ns/op 96 B/op 3 allocs/op BenchmarkASCIIFoldCustomToLowerMap-8 5000000 371 ns/op 96 B/op 3 allocs/op BenchmarkASCIIToUpper-8 20000000 104 ns/op 32 B/op 1 allocs/op BenchmarkFoldFind0-8 200000 7621 ns/op 2112 B/op 3 allocs/op BenchmarkFoldFind-8 2000000 669 ns/op 0 B/op 0 allocs/op ``` * chunked decoding unit test for parsing, reads the first chunk * fasthttp client wrapper (-http 3) - added some doc in WORKSPACE about wtool - initial support for fasthttp * Make linter happy though I might drop fasthttp as it’s not faster (but it’s more complete) and adds a lot of dependencies * Split connect out * Fixing merge error * adding fortio Logger * Fixing bazel build And misc comment/leftover from #460 etc * Shorter logger names * Switched to new logging * Eradicate Verbosity leftovers * Added -logprefix and -logcaller; Refactor start on http.go also fixed a couple of calls missing % codes * Minor edits, saving to GitHub wip * Woot http1.1 works now Still unwieldy but working ! * Some profiler optimizations * More profiler opt * Make lint happy by making checking connection closed header a flag * Dropping fasthttp dependency * Moved 3 changes to #495 * Minor: use version in echoers, use 3 digits * Code review updates (thx doug!) + serious chunked bug fix Wasn’t working with last chunk (0\r\n\r\n) being in a separate frame * Code review comment thx doug! Former-commit-id: e09dcaf
* Shrink and better document the debug image before: 722MB after: 236MB (Not counting envoy itself) Fixes istio#423 Needs istio/old_pilot_repo#1202 to fully work ```release-note Reduce proxy debug image by 2/3rd (486Mb) yet as functional ``` * Alignement fix
* Add remote profile * Update assets
Signed-off-by: Jack Tysoe <jack@tys.one> Signed-off-by: Pavel Nikolov <pavelnikolov@users.noreply.github.com> Co-authored-by: Pavel Nikolov <pavelnikolov@users.noreply.github.com>
On my Mac:
Old net/http : 19.7k qps with 2 threads (-http -1)
New -http 1 : 30.5k qps with 2 threads
And 1/8th of the user cpu consumed
Interface to select between the 2 clients
Edit:
Now works with both chunked and fixed
Content-Length (like echosrv)
Still too many ifs / readResponse function is too messy
(was intially stacked on top of #460, rerooted from master later)
This change is![Reviewable](https://camo.githubusercontent.com/23b05f5fb48215c989e92cc44cf6512512d083132bd3daf689867c8d9d386888/68747470733a2f2f72657669657761626c652e696f2f7265766965775f627574746f6e2e737667)