storage/engine: TestConcurrentBatch takes 20s+ on arm64 #15868

tamird · 2017-05-10T21:55:05Z

As of a8f1b09, on @vielmetti's Packet 2A, 96-core Cavium server running Ubuntu 16.04:

$ go version
go version go1.8.1 linux/arm64
$ go env
GOARCH="arm64"
GOBIN=""
GOEXE=""
GOHOSTARCH="arm64"
GOHOSTOS="linux"
GOOS="linux"
GOPATH="/root/go"
GORACE=""
GOROOT="/usr/lib/go-1.8"
GOTOOLDIR="/usr/lib/go-1.8/pkg/tool/linux_arm64"
GCCGO="gccgo"
CC="gcc"
GOGCCFLAGS="-fPIC -pthread -fmessage-length=0 -fdebug-prefix-map=/tmp/go-build806539295=/tmp/go-build -gno-record-gcc-switches"
CXX="g++"
CGO_ENABLED="1"
PKG_CONFIG="pkg-config"
CGO_CFLAGS="-g -O2"
CGO_CPPFLAGS=""
CGO_CXXFLAGS="-g -O2"
CGO_FFLAGS="-g -O2"
CGO_LDFLAGS="-g -O2"

$ make test PKG=./pkg/storage/engine TESTS=TestConcurrentBatch
make[1]: Nothing to be done for 'build_lib_static'.
[100%] Built target libprotobuf
make  all-am
[  0%] Built target build_version
[100%] Built target rocksdb
GEN pkg/cli/zcgo_flags.go
GEN pkg/server/status/zcgo_flags.go
GEN pkg/storage/engine/zcgo_flags.go
GEN pkg/ccl/storageccl/engineccl/zcgo_flags.go
go test -v  -tags ' make aarch64_linux_gnu' -ldflags ' -X github.com/cockroachdb/cockroach/pkg/build.typ=development' -i ./pkg/storage
go test  -tags ' make aarch64_linux_gnu' -ldflags ' -X github.com/cockroachdb/cockroach/pkg/build.typ=development' -run "TestConcurrentBatch"  -timeout 4m ./pkg/storage
ok  	github.com/cockroachdb/cockroach/pkg/storage	0.172s [no tests to run]
root@ed-ubuntu-terraform-ubuntu-golang:~/go/src/github.com/cockroachdb/cockroach# make test PKG=./pkg/storage/engine TESTS=TestConcurrentBatch
GOPATH set to /root/go
make[1]: Nothing to be done for 'build_lib_static'.
[100%] Built target libprotobuf
make  all-am
[  0%] Built target build_version
[100%] Built target rocksdb
GEN pkg/cli/zcgo_flags.go
GEN pkg/server/status/zcgo_flags.go
GEN pkg/storage/engine/zcgo_flags.go
GEN pkg/ccl/storageccl/engineccl/zcgo_flags.go
go test -v  -tags ' make aarch64_linux_gnu' -ldflags ' -X github.com/cockroachdb/cockroach/pkg/build.typ=development' -i ./pkg/storage/engine
go test  -tags ' make aarch64_linux_gnu' -ldflags ' -X github.com/cockroachdb/cockroach/pkg/build.typ=development' -run "TestConcurrentBatch"  -timeout 4m ./pkg/storage/engine
I170510 21:51:28.883461 5 storage/engine/rocksdb.go:379  opening rocksdb instance at "/tmp/TestConcurrentBatch610155995"
W170510 21:51:33.251407 166 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 1.39664568s (>500ms):
goroutine 166 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442053c000, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442053c000, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442053c000)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:34.674659 162 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 2.82117415s (>500ms):
goroutine 162 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021d680, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021d680, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021d680)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:36.121045 9 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 4.26748797s (>500ms):
goroutine 9 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021c240, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021c240, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021c240)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:37.613640 164 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 5.76009689s (>500ms):
goroutine 164 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021db00, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021db00, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021db00)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:39.068514 7 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 7.21496604s (>500ms):
goroutine 7 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442041fd40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442041fd40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442041fd40)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:40.469884 11 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 8.61620546s (>500ms):
goroutine 11 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021c900, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021c900, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021c900)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:41.896595 165 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 10.04266145s (>500ms):
goroutine 165 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021dd40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021dd40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021dd40)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:43.479268 16 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 11.62519902s (>500ms):
goroutine 16 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021d440, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021d440, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021d440)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:44.914574 163 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 13.06077748s (>500ms):
goroutine 163 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021d8c0, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021d8c0, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021d8c0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:46.402015 12 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 14.54822675s (>500ms):
goroutine 12 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021cb40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021cb40, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021cb40)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:47.706971 8 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 15.85290138s (>500ms):
goroutine 8 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021c000, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021c000, 0x4434717100, 0x44204ec940, 0x589eac)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021c000)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:49.199277 13 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 17.3458283s (>500ms):
goroutine 13 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021cd80, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021cd80, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021cd80)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:50.706410 10 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 18.85274765s (>500ms):
goroutine 10 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021c480, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021c480, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021c480)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:52.137329 15 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 20.2832925s (>500ms):
goroutine 15 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021d200, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021d200, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021d200)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:53.589440 14 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 21.73536757s (>500ms):
goroutine 14 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442021cfc0, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442021cfc0, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442021cfc0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
W170510 21:51:54.991398 6 storage/engine/rocksdb.go:1236  batch [355017/4194314/0] commit took 23.13761362s (>500ms):
goroutine 6 [running]:
runtime/debug.Stack(0xdc5520, 0x1352fe0, 0x44200e6d80)
	/usr/lib/go-1.8/src/runtime/debug/stack.go:24 +0x5c
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).commitInternal(0x442041fb00, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1236 +0x108
github.com/cockroachdb/cockroach/pkg/storage/engine.(*rocksDBBatch).Commit(0x442041fb00, 0x0, 0x0, 0x0)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb.go:1205 +0x528
github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch.func2(0x44203e02a0, 0x1357fc0, 0x442041fb00)
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:391 +0x2c
created by github.com/cockroachdb/cockroach/pkg/storage/engine.TestConcurrentBatch
	/root/go/src/github.com/cockroachdb/cockroach/pkg/storage/engine/rocksdb_test.go:392 +0x4ec
I170510 21:51:54.991972 5 storage/engine/rocksdb.go:446  closing rocksdb instance at "/tmp/TestConcurrentBatch610155995"
--- FAIL: TestConcurrentBatch (26.81s)
	rocksdb_test.go:416: write took 23.0s
FAIL
FAIL	github.com/cockroachdb/cockroach/pkg/storage/engine	26.988s
Makefile:193: recipe for target 'test' failed
make: *** [test] Error 1

The text was updated successfully, but these errors were encountered:

bdarnell · 2017-05-10T22:17:41Z

Possibly related to #15604. This test is flaky on my laptop too, although in my case it passes when run in isolation.

petermattis · 2017-05-15T14:09:33Z

Kind of scary that writing 16 4MB batches takes 20+ seconds. Can we do some simple I/O benchmarks on this machine?

~ dd if=/dev/zero of=testfile bs=1024 count=$[1024 * 1024]

tamird · 2017-05-15T14:42:17Z

$ dd if=/dev/zero of=testfile bs=1024 count=$[1024 * 1024]
1048576+0 records in
1048576+0 records out
1073741824 bytes (1.1 GB, 1.0 GiB) copied, 6.56604 s, 164 MB/s

petermattis · 2017-05-15T14:46:03Z

Hmm, that seems fast enough.

vielmetti · 2017-05-15T18:06:29Z

The code reads

		// This write can get delayed excessively if we hit the max memtable count
		// or the L0 stop writes threshold.

petermattis · 2017-05-15T18:33:43Z

@vielmetti Right, but we shouldn't be hitting that limit given how we configure RocksDB. level0_stop_writes_trigger is set to 32 and the memtable budget is 128MB. Clearly we don't know what is going on here. I'm planning to take a look later.

petermattis · 2017-05-15T18:54:40Z

I think we're just seeing the speed of the ARM processors. This is the difference in performance for one of the configurations for the MVCCBatchPut benchmark:

~ benchstat out.darwin out.arm
name                                old time/op    new time/op    delta
MVCCBatchPut_RocksDB/10000x10Bytes    4.27µs ± 5%   37.36µs ±12%  +775.53%  (p=0.000 n=20+19)

petermattis · 2017-05-15T18:59:09Z

The MVCCBatchPut benchmark is 7.8x faster on my (Mac OS X) laptop than the ARM machine. TestConcurrentBatch is 8.43x faster on my laptop. That's close enough to be the smoking gun.

bdarnell · 2017-05-15T19:17:39Z

It might be interesting to run a quick CPU profile on arm to see if there are any obvious spots for improvement. For example, we do a lot of CRC32s, both in our code and in rocksdb. Both intel and arm architectures have hardware acceleration for this (at least in recent chips), but Go and rocksdb only know how to use the intel versions.

vielmetti · 2017-05-15T19:31:53Z

Looks like help is on its way for accelerated crc32's, based on

https://go-review.googlesource.com/c/40074/

hash/crc32: optimize arm64 crc32 implementation

ARMv8 defines crc32 instruction.

Comparing to the original crc32 calculation, this patch makes use of
crc32 instructions to do crc32 calculation instead of the multiple
lookup table algorithms.

ARMv8 provides IEEE and Castagnoli polynomials for crc32 calculation
so that the perfomance of these two types of crc32 get significant
improved.

name                                        old time/op   new time/op    delta
CRC32/poly=IEEE/size=15/align=0-32            117ns ± 0%      38ns ± 0%   -67.44%
CRC32/poly=IEEE/size=15/align=1-32            117ns ± 0%      38ns ± 0%   -67.52%
CRC32/poly=IEEE/size=40/align=0-32            129ns ± 0%      41ns ± 0%   -68.37%
CRC32/poly=IEEE/size=40/align=1-32            129ns ± 0%      41ns ± 0%   -68.29%
CRC32/poly=IEEE/size=512/align=0-32           828ns ± 0%     246ns ± 0%   -70.29%
CRC32/poly=IEEE/size=512/align=1-32           828ns ± 0%     132ns ± 0%   -84.06%
CRC32/poly=IEEE/size=1kB/align=0-32          1.58µs ± 0%    0.46µs ± 0%   -70.98%
CRC32/poly=IEEE/size=1kB/align=1-32          1.58µs ± 0%    0.46µs ± 0%   -70.92%
CRC32/poly=IEEE/size=4kB/align=0-32          6.06µs ± 0%    1.74µs ± 0%   -71.27%
CRC32/poly=IEEE/size=4kB/align=1-32          6.10µs ± 0%    1.74µs ± 0%   -71.44%
CRC32/poly=IEEE/size=32kB/align=0-32         48.3µs ± 0%    13.7µs ± 0%   -71.61%
CRC32/poly=IEEE/size=32kB/align=1-32         48.3µs ± 0%    13.7µs ± 0%   -71.60%
CRC32/poly=Castagnoli/size=15/align=0-32      116ns ± 0%      38ns ± 0%   -67.07%

ARMv8 defines crc32 instruction. Comparing to the original crc32 calculation, this patch makes use of crc32 instructions to do crc32 calculation instead of the multiple lookup table algorithms. ARMv8 provides IEEE and Castagnoli polynomials for crc32 calculation so that the perfomance of these two types of crc32 get significant improved. name old time/op new time/op delta CRC32/poly=IEEE/size=15/align=0-32 117ns ± 0% 38ns ± 0% -67.44% CRC32/poly=IEEE/size=15/align=1-32 117ns ± 0% 38ns ± 0% -67.52% CRC32/poly=IEEE/size=40/align=0-32 129ns ± 0% 41ns ± 0% -68.37% CRC32/poly=IEEE/size=40/align=1-32 129ns ± 0% 41ns ± 0% -68.29% CRC32/poly=IEEE/size=512/align=0-32 828ns ± 0% 246ns ± 0% -70.29% CRC32/poly=IEEE/size=512/align=1-32 828ns ± 0% 132ns ± 0% -84.06% CRC32/poly=IEEE/size=1kB/align=0-32 1.58µs ± 0% 0.46µs ± 0% -70.98% CRC32/poly=IEEE/size=1kB/align=1-32 1.58µs ± 0% 0.46µs ± 0% -70.92% CRC32/poly=IEEE/size=4kB/align=0-32 6.06µs ± 0% 1.74µs ± 0% -71.27% CRC32/poly=IEEE/size=4kB/align=1-32 6.10µs ± 0% 1.74µs ± 0% -71.44% CRC32/poly=IEEE/size=32kB/align=0-32 48.3µs ± 0% 13.7µs ± 0% -71.61% CRC32/poly=IEEE/size=32kB/align=1-32 48.3µs ± 0% 13.7µs ± 0% -71.60% CRC32/poly=Castagnoli/size=15/align=0-32 116ns ± 0% 38ns ± 0% -67.07% CRC32/poly=Castagnoli/size=15/align=1-32 116ns ± 0% 38ns ± 0% -66.90% CRC32/poly=Castagnoli/size=40/align=0-32 127ns ± 0% 40ns ± 0% -68.11% CRC32/poly=Castagnoli/size=40/align=1-32 127ns ± 0% 40ns ± 0% -68.11% CRC32/poly=Castagnoli/size=512/align=0-32 828ns ± 0% 132ns ± 0% -84.06% CRC32/poly=Castagnoli/size=512/align=1-32 827ns ± 0% 132ns ± 0% -84.04% CRC32/poly=Castagnoli/size=1kB/align=0-32 1.59µs ± 0% 0.22µs ± 0% -85.89% CRC32/poly=Castagnoli/size=1kB/align=1-32 1.58µs ± 0% 0.22µs ± 0% -85.79% CRC32/poly=Castagnoli/size=4kB/align=0-32 6.14µs ± 0% 0.77µs ± 0% -87.40% CRC32/poly=Castagnoli/size=4kB/align=1-32 6.06µs ± 0% 0.77µs ± 0% -87.25% CRC32/poly=Castagnoli/size=32kB/align=0-32 48.3µs ± 0% 5.9µs ± 0% -87.71% CRC32/poly=Castagnoli/size=32kB/align=1-32 48.4µs ± 0% 6.0µs ± 0% -87.69% CRC32/poly=Koopman/size=15/align=0-32 104ns ± 0% 104ns ± 0% +0.00% CRC32/poly=Koopman/size=15/align=1-32 104ns ± 0% 104ns ± 0% +0.00% CRC32/poly=Koopman/size=40/align=0-32 235ns ± 0% 235ns ± 0% +0.00% CRC32/poly=Koopman/size=40/align=1-32 235ns ± 0% 235ns ± 0% +0.00% CRC32/poly=Koopman/size=512/align=0-32 2.71µs ± 0% 2.71µs ± 0% -0.07% CRC32/poly=Koopman/size=512/align=1-32 2.71µs ± 0% 2.71µs ± 0% -0.04% CRC32/poly=Koopman/size=1kB/align=0-32 5.40µs ± 0% 5.39µs ± 0% -0.06% CRC32/poly=Koopman/size=1kB/align=1-32 5.40µs ± 0% 5.40µs ± 0% +0.02% CRC32/poly=Koopman/size=4kB/align=0-32 21.5µs ± 0% 21.5µs ± 0% -0.16% CRC32/poly=Koopman/size=4kB/align=1-32 21.5µs ± 0% 21.5µs ± 0% -0.05% CRC32/poly=Koopman/size=32kB/align=0-32 172µs ± 0% 172µs ± 0% -0.07% CRC32/poly=Koopman/size=32kB/align=1-32 172µs ± 0% 172µs ± 0% -0.01% name old speed new speed delta CRC32/poly=IEEE/size=15/align=0-32 128MB/s ± 0% 394MB/s ± 0% +207.95% CRC32/poly=IEEE/size=15/align=1-32 128MB/s ± 0% 394MB/s ± 0% +208.09% CRC32/poly=IEEE/size=40/align=0-32 310MB/s ± 0% 979MB/s ± 0% +216.07% CRC32/poly=IEEE/size=40/align=1-32 310MB/s ± 0% 979MB/s ± 0% +216.16% CRC32/poly=IEEE/size=512/align=0-32 618MB/s ± 0% 2074MB/s ± 0% +235.72% CRC32/poly=IEEE/size=512/align=1-32 618MB/s ± 0% 3852MB/s ± 0% +523.55% CRC32/poly=IEEE/size=1kB/align=0-32 646MB/s ± 0% 2225MB/s ± 0% +244.57% CRC32/poly=IEEE/size=1kB/align=1-32 647MB/s ± 0% 2225MB/s ± 0% +243.87% CRC32/poly=IEEE/size=4kB/align=0-32 676MB/s ± 0% 2352MB/s ± 0% +248.02% CRC32/poly=IEEE/size=4kB/align=1-32 672MB/s ± 0% 2352MB/s ± 0% +250.15% CRC32/poly=IEEE/size=32kB/align=0-32 678MB/s ± 0% 2387MB/s ± 0% +252.17% CRC32/poly=IEEE/size=32kB/align=1-32 678MB/s ± 0% 2388MB/s ± 0% +252.11% CRC32/poly=Castagnoli/size=15/align=0-32 129MB/s ± 0% 393MB/s ± 0% +205.51% CRC32/poly=Castagnoli/size=15/align=1-32 129MB/s ± 0% 390MB/s ± 0% +203.41% CRC32/poly=Castagnoli/size=40/align=0-32 314MB/s ± 0% 988MB/s ± 0% +215.04% CRC32/poly=Castagnoli/size=40/align=1-32 314MB/s ± 0% 987MB/s ± 0% +214.68% CRC32/poly=Castagnoli/size=512/align=0-32 618MB/s ± 0% 3860MB/s ± 0% +524.32% CRC32/poly=Castagnoli/size=512/align=1-32 619MB/s ± 0% 3859MB/s ± 0% +523.66% CRC32/poly=Castagnoli/size=1kB/align=0-32 645MB/s ± 0% 4568MB/s ± 0% +608.56% CRC32/poly=Castagnoli/size=1kB/align=1-32 650MB/s ± 0% 4567MB/s ± 0% +602.94% CRC32/poly=Castagnoli/size=4kB/align=0-32 667MB/s ± 0% 5297MB/s ± 0% +693.81% CRC32/poly=Castagnoli/size=4kB/align=1-32 676MB/s ± 0% 5297MB/s ± 0% +684.00% CRC32/poly=Castagnoli/size=32kB/align=0-32 678MB/s ± 0% 5519MB/s ± 0% +713.83% CRC32/poly=Castagnoli/size=32kB/align=1-32 677MB/s ± 0% 5497MB/s ± 0% +712.04% CRC32/poly=Koopman/size=15/align=0-32 143MB/s ± 0% 144MB/s ± 0% +0.27% CRC32/poly=Koopman/size=15/align=1-32 143MB/s ± 0% 144MB/s ± 0% +0.33% CRC32/poly=Koopman/size=40/align=0-32 169MB/s ± 0% 170MB/s ± 0% +0.12% CRC32/poly=Koopman/size=40/align=1-32 170MB/s ± 0% 170MB/s ± 0% +0.08% CRC32/poly=Koopman/size=512/align=0-32 189MB/s ± 0% 189MB/s ± 0% +0.07% CRC32/poly=Koopman/size=512/align=1-32 189MB/s ± 0% 189MB/s ± 0% +0.04% CRC32/poly=Koopman/size=1kB/align=0-32 190MB/s ± 0% 190MB/s ± 0% +0.05% CRC32/poly=Koopman/size=1kB/align=1-32 190MB/s ± 0% 190MB/s ± 0% -0.01% CRC32/poly=Koopman/size=4kB/align=0-32 190MB/s ± 0% 190MB/s ± 0% +0.15% CRC32/poly=Koopman/size=4kB/align=1-32 190MB/s ± 0% 191MB/s ± 0% +0.05% CRC32/poly=Koopman/size=32kB/align=0-32 191MB/s ± 0% 191MB/s ± 0% +0.06% CRC32/poly=Koopman/size=32kB/align=1-32 191MB/s ± 0% 191MB/s ± 0% +0.02% Also fix a bug of arm64 assembler The optimization is mainly contributed by Fangming.Fang <fangming.fang@arm.com> Change-Id: I900678c2e445d7e8ad9e2a9ab3305d649230905f Reviewed-on: https://go-review.googlesource.com/40074 Reviewed-by: Cherry Zhang <cherryyz@google.com> Run-TryBot: Cherry Zhang <cherryyz@google.com> TryBot-Result: Gobot Gobot <gobot@golang.org>

vielmetti · 2017-05-15T20:03:40Z

OK, the issue is open on the Go side. Just looking at Go's release schedule, it appears most likely that the earliest this could possibly be addressed is in 1.9, since 1.8.2 looks very much like a bug fix release. That puts us into the end of July. I'll see if there's some stable tip build or RC that we can try before then to validate performance and correctness.

Update: "the code has been merged" and will definitely be in 1.9.

petermattis · 2017-05-15T20:06:59Z

Ben's guess at CRC32 being the culprit is just a guess. Actual profiling should be done too.

petermattis · 2017-05-16T13:28:27Z

This was likely helped by #15943. @tamird Can you re-check the timing of TestConcurrentBatch on arm?

tamird · 2017-05-16T14:45:43Z

Yeah, it passed now:

go test  -tags ' make aarch64_linux_gnu' -ldflags ' -X github.com/cockroachdb/cockroach/pkg/build.typ=development' -run "TestConcurrentBatch"  -timeout 4m ./pkg/storage/engine
ok  	github.com/cockroachdb/cockroach/pkg/storage/engine	12.799s

But it's still real slow!

petermattis · 2017-05-16T15:01:35Z

The processors are slow, so this is to be expected.

vielmetti · 2017-05-16T17:12:36Z

Yes, the processors are at 2 Ghz for reference.

Also, yay, test passed.

petermattis · 2017-06-01T17:35:57Z

Closing as I don't think there is anything actionable left to do here.

tamird mentioned this issue May 10, 2017

CockroachDB build on ARMv8 (aarch64, arm64) Ubuntu 16.04 + Go 1.8 #14405

Closed

vielmetti mentioned this issue May 15, 2017

hash/crc32: optimize arm64 crc32 implementation golang/go#20370

Closed

petermattis closed this as completed Jun 1, 2017

jordanlewis added the B-unsupported-arch Non-x86_64 architectures: PPC, MIPS, etc label Apr 23, 2018

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

storage/engine: TestConcurrentBatch takes 20s+ on arm64 #15868

storage/engine: TestConcurrentBatch takes 20s+ on arm64 #15868

tamird commented May 10, 2017

bdarnell commented May 10, 2017

petermattis commented May 15, 2017

tamird commented May 15, 2017

petermattis commented May 15, 2017

vielmetti commented May 15, 2017

petermattis commented May 15, 2017

petermattis commented May 15, 2017

petermattis commented May 15, 2017

bdarnell commented May 15, 2017

vielmetti commented May 15, 2017

vielmetti commented May 15, 2017 •

edited

petermattis commented May 15, 2017

petermattis commented May 16, 2017

tamird commented May 16, 2017

petermattis commented May 16, 2017

vielmetti commented May 16, 2017 •

edited

petermattis commented Jun 1, 2017

storage/engine: TestConcurrentBatch takes 20s+ on arm64 #15868

storage/engine: TestConcurrentBatch takes 20s+ on arm64 #15868

Comments

tamird commented May 10, 2017

bdarnell commented May 10, 2017

petermattis commented May 15, 2017

tamird commented May 15, 2017

petermattis commented May 15, 2017

vielmetti commented May 15, 2017

petermattis commented May 15, 2017

petermattis commented May 15, 2017

petermattis commented May 15, 2017

bdarnell commented May 15, 2017

vielmetti commented May 15, 2017

vielmetti commented May 15, 2017 • edited

petermattis commented May 15, 2017

petermattis commented May 16, 2017

tamird commented May 16, 2017

petermattis commented May 16, 2017

vielmetti commented May 16, 2017 • edited

petermattis commented Jun 1, 2017

vielmetti commented May 15, 2017 •

edited

vielmetti commented May 16, 2017 •

edited