make event logging configurable

[elagergren-spideroak]

What version of Go are you using (go version)?

$ go version
1.12.7

What version of Badger are you using?

v1.6.0

What did you do?

Ran benchmarks using badgerdb.

What did you expect to see?

I didn't expect to see logging appear on the CPU profile.

What did you see instead?

It did, and there's no way to turn it off.

In some of my benchmarks ~10% of the time spent inside (*DB).doWrites (and more elsewhere!) is spent printing to the event log. ISTM there's no way to disable this.

[ashish-goswami]

Hey @elagergren-spideroak, how were you running benchmarks?
You can try to avoid logging by calling options.WithLogger(false).

[martinmr]

This is how you configure the logger: https://github.com/dgraph-io/badger/blob/1496af939d8533779f7b6b3f3a6cd251abf5c598/options.go#L231

In your case you'd create a logger that takes the input but returns immediately without doing anything with it.

[elagergren-spideroak]

The issue isn't that logger, it's the event logger. See:

[elagergren-spideroak]

I've set the WithLogger(nil) option already, as well as tried a nop logger.

[divyakoshy]

I've set the WithLogger(nil) option already, as well as tried a nop logger.

This seems to work:

        opts := badger.DefaultOptions("./.badgerdb")
	db, err := badger.Open(opts.WithLogger(nil))

[ericlagergren]

Note that I’m not talking about general logging, I’m talking about event logging from x/net/trace.

https://github.com/dgraph-io/badger/blob/e627d49fa7e9ddf9c31a833e83c4b3937bb81c66/db.go#L280

See also my screenshot.

[campoy]

Are you running pprof while running your benchmarks?
In that case this is expected and a side effect of pprof itself, rather than a bug in badger.

Could you share the whole pprof trace you obtained? Both web and top -cum output would be great

[mjgarton]

I seem to have the same issue.

@campoy can you explain what you mean by "running pprof while running your benchmarks"?

In my case, the application calls pprof.StartCPUProfile at the start and pprof.StopCPUProfile at the end. Is that what you mean?

[mjgarton]

Also here is top20 -cum:

(pprof) top20 -cum
Showing nodes accounting for 0.62mins, 2.36% of 26.24mins total
Dropped 663 nodes (cum <= 0.13mins)
Showing top 20 nodes out of 196
      flat  flat%   sum%        cum   cum%
  0.02mins 0.093% 0.093%   9.21mins 35.09%  github.com/dgraph-io/badger.(*DB).doWrites.func1
  0.06mins  0.22%  0.31%   9.14mins 34.83%  github.com/dgraph-io/badger.(*DB).writeRequests
         0     0%  0.31%   7.02mins 26.77%  github.com/urfave/cli.(*App).Run
         0     0%  0.31%   7.02mins 26.77%  github.com/urfave/cli.Command.Run
         0     0%  0.31%   7.02mins 26.77%  github.com/urfave/cli.HandleAction
         0     0%  0.31%   7.02mins 26.77%  main.badgerLoad
         0     0%  0.31%   7.02mins 26.77%  main.main
         0     0%  0.31%   7.02mins 26.77%  main.main.func9
         0     0%  0.31%   7.02mins 26.77%  runtime.main
         0     0%  0.31%      7mins 26.69%  path/filepath.Walk
         0     0%  0.31%      7mins 26.69%  path/filepath.walk
         0     0%  0.31%      7mins 26.69%  main.load
  0.04mins  0.14%  0.46%      7mins 26.69%  main.load.func1
  0.02mins 0.068%  0.52%   5.90mins 22.49%  golang.org/x/net/trace.(*eventLog).Printf
  0.16mins  0.62%  1.14%   5.88mins 22.42%  golang.org/x/net/trace.(*eventLog).printf
  0.14mins  0.55%  1.69%   4.88mins 18.61%  main.(*badgerRecordHandler).HandleRecord
  0.06mins  0.23%  1.93%   4.13mins 15.75%  fmt.Sprintf
  0.04mins  0.15%  2.07%   3.80mins 14.47%  github.com/dgraph-io/badger.(*DB).Update
  0.03mins  0.12%  2.19%   3.79mins 14.45%  runtime.mcall
  0.04mins  0.17%  2.36%   3.77mins 14.37%  github.com/dgraph-io/badger.(*valueLog).write

[mjgarton]

FWIW these same Printf calls are also responsible for a good chunk of allocations in some of my applications.

Also, if someone can suggest what the API for this configuration should look, I may take a stab at implementing it.

[campoy]

Yes, that's what I meant.
Thanks for the extra info, @mjgarton.

@jarifibrahim, please have a look and see whether there's any improvements we can make and how you can guide Martin with his implementation