Redis profiling experiment #442

urso · 2015-12-04T01:58:18Z

Did play with golang pprof tool today + redis pcap files. This PR hugely reduces number of objects allocated by redis-module itself. When replaying redis traffic only object allocations are mostly dominated by the json encoder (the output worker directly calls console outputer doing json encoding):

(pprof) top20 -cum
2809008 of 6861983 total (40.94%)
Dropped 48 nodes (cum <= 34309)
Showing top 20 nodes out of 61 (cum >= 1385433)
    flat  flat%   sum%        cum   cum%
        0     0%     0%    6860618   100%  runtime.goexit
        0     0%     0%    3767472 54.90%  github.com/elastic/beats/libbeat/publisher.(*messageWorker).run
        0     0%     0%    2834909 41.31%  github.com/elastic/beats/libbeat/publisher.(*outputWorker).onBulk
        0     0%     0%    2834909 41.31%  github.com/elastic/beats/libbeat/publisher.(*outputWorker).onMessage
    229379  3.34%  3.34%    2834909 41.31%  github.com/elastic/beats/libbeat/publisher.(*outputWorker).sendBulk
    56608  0.82%  4.17%    2605530 37.97%  encoding/json.Marshal
        0     0%  4.17%    2605530 37.97%  github.com/elastic/beats/libbeat/outputs.(*bulkOutputAdapter).BulkPublish
        0     0%  4.17%    2605530 37.97%  github.com/elastic/beats/libbeat/outputs/console.(*console).PublishEvent
        0     0%  4.17%    2578716 37.58%  encoding/json.(*encodeState).marshal
        0     0%  4.17%    2578716 37.58%  encoding/json.(*encodeState).reflectValue
        0     0%  4.17%    2578716 37.58%  encoding/json.(*mapEncoder).(encoding/json.encode)-fm
    81922  1.19%  5.36%    2578716 37.58%  encoding/json.(*mapEncoder).encode
        0     0%  5.36%    2220027 32.35%  github.com/elastic/beats/packetbeat/beat.(*Packetbeat).Run.func1
    196612  2.87%  8.23%    2220027 32.35%  github.com/elastic/beats/packetbeat/sniffer.(*SnifferSetup).Run
    71010  1.03%  9.26%    1849392 26.95%  github.com/elastic/beats/packetbeat/decoder.(*DecoderStruct).DecodePacketData
    377929  5.51% 14.77%    1774285 25.86%  github.com/elastic/beats/packetbeat/protos/tcp.(*Tcp).Process
1458197 21.25% 36.02%    1458197 21.25%  reflect.unsafe_New
        0     0% 36.02%    1396356 20.35%  github.com/elastic/beats/packetbeat/protos/redis.(*Redis).Parse
        0     0% 36.02%    1396356 20.35%  github.com/elastic/beats/packetbeat/protos/tcp.(*TcpStream).addPacket
    337351  4.92% 40.94%    1385433 20.19%  github.com/elastic/beats/packetbeat/protos/redis.(*Redis).doParse

TODO: some benchmarking on redis module to check if allocations really make a big difference.

changes

added commandline flag '-httpprof' to start HTTP pprof endpoint for doing
some live profiling of beat services (heap profiling, cpu profiling)
add streambuf.AppendWithCapLimits which guarantees newly allocated
buffers have at least configured capacity in case the buffer
must grow when appending new content (excert more control on buffer sizing)
=> not used, as number of objects allocated was minor in contrast to
other object types. Plus bad policy can increase overal memory usage
dramatically due to pointers back into original slice
add common.NetString basically being []byte. Difference to []byte is, this
type implements the encoding.TextMarhsaller interface. NetString objects
will be handled by JSON encoder like normal strings, thusly no allocation
and copy is required when extracting strings from parsed messages.
NetString being []byte will directly point into original message buffer.

NetString also provides UnsafeString to cast a NetString into a string
without allocation + copy

=> Using NetString over string reduce allocations + copy operations +
less object to be GCed
remove some unwanted allocation in async publisher client
redis 'optimizations':
- replace all string types with common.NetString to reduce allocations
- pre-allocate command buffer holding command + 4 arguments by default
- remove some more allocations + copies by 'low-level code'
- remove transaction object type (not required anymore due to correlation
  supporting piping), but generate event type directly from correlated
  messages => reduces allocation once more + removes computation of unused
  fields

andrewkroh · 2015-12-04T13:47:54Z

libbeat/common/string.go

+func (n NetString) UnsafeString() string {
+	bh := (*reflect.SliceHeader)(unsafe.Pointer(&n))
+	sh := reflect.StringHeader{Data: bh.Data, Len: bh.Len}
+	return *(*string)(unsafe.Pointer(&sh))


Go performs a copy when converting from []byte to string to guarantee that the contents of the string can not be changed by mutating the []byte since the contract in Go is that strings are immutable.

This seems like a good optimization to use when you know for sure that the returned string is not going to be retained (where immutability guarantees might be required). The method should get updated to document when and how to safely use it.

Not sure we want to get ourselves in the Unsafe territory. How much do we win in terms of performance? Perhaps we can find another way to avoid the copy by refactoring at an upper layer.

Not keen about unsafe territory either. That's why introduced NetString over unsafe copying all []byte into string. Purpose of this method is to be used with map lookups (map keys can not be []byte, but must be string) in cases of compiler not optimizing []byte into string conversion. Optimized version in disassembly contains runtime.slicebytetostringtmp, unoptimized with copy will be runtime.slicebytetostring).

Not required anymore. Rather remove it.

Did you intend to remove the method before merging?

oh, I thought I removed it. Will be removed.

andrewkroh · 2015-12-04T13:52:13Z

I like the -httpprof flag. I am always modifying the source to drop in the HTTP server to enable pprof.

urso · 2015-12-04T16:27:40Z

yep, also like to have -httpprof. you can run packetbeat with '-httpprof :6060' to have to locally on port 6060 ;)

urso · 2015-12-04T22:53:31Z

added some very simple/small benchmarks for redis parser only (does not take the removed allocations for removal of redundant transaction object into account):

old parser (using string):

BenchmarkParserNoArgsResult-4    1000000          1414 ns/op         464 B/op          9 allocs/op
BenchmarkParserArrayRequest-4    1000000          2108 ns/op         592 B/op         15 allocs/op
BenchmarkParserArrayResponse-4   1000000          2420 ns/op         688 B/op         17 allocs/op
BenchmarkParserArrayNested-4     1000000          3223 ns/op         896 B/op         26 allocs/op
BenchmarkParserArray2Passes-4     500000          3390 ns/op         832 B/op         24 allocs/op

new parser (using NetString):

BenchmarkParserNoArgsResult-4    1000000          1338 ns/op         448 B/op          6 allocs/op
BenchmarkParserArrayRequest-4    1000000          1551 ns/op         448 B/op          6 allocs/op
BenchmarkParserArrayResponse-4   1000000          1598 ns/op         464 B/op          6 allocs/op
BenchmarkParserArrayNested-4     1000000          2263 ns/op         640 B/op         13 allocs/op
BenchmarkParserArray2Passes-4    1000000          2302 ns/op         576 B/op         10 allocs/op

Allocations and runtime are reduced (some allocations are due to test setup).

tsg · 2015-12-07T23:01:44Z

LGTM! Do you want to cleanup history before merging?

tsg · 2015-12-07T23:03:21Z

Also a line in the Changelog about the Redis parser being faster would be good.

urso · 2015-12-07T23:06:49Z

let me cleanup first

urso · 2015-12-08T00:28:10Z

cleaned up history + guarded all debug statements.

New benchmark results:

BenchmarkParserNoArgsResult-4    1000000          1069 ns/op         368 B/op          3 allocs/op
BenchmarkParserArrayRequest-4    1000000          1292 ns/op         368 B/op          3 allocs/op
BenchmarkParserArrayResponse-4   1000000          1331 ns/op         384 B/op          3 allocs/op
BenchmarkParserArrayNested-4     1000000          1457 ns/op         400 B/op          4 allocs/op
BenchmarkParserArray2Passes-4    1000000          1804 ns/op         416 B/op          4 allocs/op

andrewkroh · 2015-12-08T04:09:14Z

libbeat/service/service.go


 func init() {
 	memprofile = flag.String("memprofile", "", "Write memory profile to this file")
 	cpuprofile = flag.String("cpuprofile", "", "Write cpu profile to file")
+	httpprof = flag.String("httpprof", "", "Start pprof http server")


This option needs added to the docs.

monicasarbu · 2015-12-08T10:55:25Z

That's incredible. Great work, Steffen!

- added commandline flag '-httpprof' to start HTTP pprof endpoint for doing some live profiling of beat services (heap profiling, cpu profiling) - add streambuf.AppendWithCapLimits which guarantees newly allocated buffers have at least configured capacity in case the buffer must grow when appending new content (excert more control on buffer sizing) => not used, as number of objects allocated was minor in contrast to other object types. Plus bad policy can increase overal memory usage dramatically due to pointers back into original slice - add common.NetString basically being []byte. Difference to []byte is, this type implements the encoding.TextMarhsaller interface. NetString objects will be handled by JSON encoder like normal strings, thusly no allocation and copy is required when extracting strings from parsed messages. NetString being []byte will directly point into original message buffer. NetString also provides UnsafeString to cast a NetString into a string without allocation + copy => Using NetString over string reduce allocations + copy operations + less object to be GCed - remove some unwanted allocation in async publisher client - redis 'optimizations': - replace all string types with common.NetString to reduce allocations - pre-allocate command buffer holding command + 4 arguments by default - remove some more allocations + copies by 'low-level code' - remove transaction object type (not required anymore due to correlation supporting piping), but generate event type directly from correlated messages => reduces allocation once more + removes computation of unused fields

ruflin · 2015-12-08T13:56:47Z

@urso As @travis-ci seems to be broken at the moment I suggest to rely on our Jenkins build.

Redis profiling experiment

urso added the discuss Issue needs further discussion. label Dec 4, 2015

andrewkroh reviewed Dec 4, 2015
View reviewed changes

urso force-pushed the prof/redis branch 2 times, most recently from 4206e37 to 32c7ea6 Compare December 5, 2015 23:14

urso added the review label Dec 6, 2015

tsg added the Packetbeat label Dec 7, 2015

urso mentioned this pull request Dec 7, 2015

http parser performance #468

Merged

Add benchmarks to redis_test

da485a3

urso force-pushed the prof/redis branch from 32c7ea6 to d218f95 Compare December 8, 2015 00:26

andrewkroh reviewed Dec 8, 2015
View reviewed changes

urso added 3 commits December 8, 2015 14:09

Guard redis debug statement

0528cee

add -httpprof CLI to docs

41a77b8

urso force-pushed the prof/redis branch from d218f95 to 41a77b8 Compare December 8, 2015 13:09

Async publisher implement eventPublisher directly

21d395a

andrewkroh added a commit that referenced this pull request Dec 8, 2015

Merge pull request #442 from urso/prof/redis

8a45017

Redis profiling experiment

andrewkroh merged commit 8a45017 into elastic:master Dec 8, 2015

urso deleted the prof/redis branch December 8, 2015 18:18

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Redis profiling experiment #442

Redis profiling experiment #442

urso commented Dec 4, 2015

andrewkroh Dec 4, 2015

tsg Dec 4, 2015

urso Dec 4, 2015

urso Dec 4, 2015

andrewkroh Dec 8, 2015

urso Dec 8, 2015

andrewkroh commented Dec 4, 2015

urso commented Dec 4, 2015

urso commented Dec 4, 2015

tsg commented Dec 7, 2015

tsg commented Dec 7, 2015

urso commented Dec 7, 2015

urso commented Dec 8, 2015

andrewkroh Dec 8, 2015

urso Dec 8, 2015

monicasarbu commented Dec 8, 2015

ruflin commented Dec 8, 2015

Redis profiling experiment #442

Redis profiling experiment #442

Conversation

urso commented Dec 4, 2015

changes

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

Choose a reason for hiding this comment

andrewkroh commented Dec 4, 2015

urso commented Dec 4, 2015

urso commented Dec 4, 2015

tsg commented Dec 7, 2015

tsg commented Dec 7, 2015

urso commented Dec 7, 2015

urso commented Dec 8, 2015

Choose a reason for hiding this comment

Choose a reason for hiding this comment

monicasarbu commented Dec 8, 2015

ruflin commented Dec 8, 2015