Skip to content
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.

Sign up for GitHub

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

Jump to bottom

ccl/partitionccl: TestInitialPartitioning failed under stress [skipped] #28789

Closed
cockroach-teamcity opened this issue Aug 18, 2018 · 13 comments
Closed

ccl/partitionccl: TestInitialPartitioning failed under stress [skipped] #28789

cockroach-teamcity opened this issue Aug 18, 2018 · 13 comments
Assignees
@petermattis
Labels
A-partitioning C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
2.1

Comments

@cockroach-teamcity
Copy link
Member

SHA: https://github.com/cockroachdb/cockroach/commits/8bd6caec6eed07ecff29801f3f11993352544387

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=846134&tab=buildLog

   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2392] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=44901964,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=44901964,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=44901964,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޻
cockroach.streamid: 1
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=07ffa549,n2] querying next range at /Table/64/1/1
  [txn=07ffa549,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=07ffa549,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: [async] drain ===
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 1.281ms
  [n2] accumulation complete
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2393] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:42.842527 1257 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180818 06:14:43.767985 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a > 4
I180818 06:14:43.900795 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:44.096171 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:44.223778 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2410] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2410] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=932f6847,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=932f6847,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=932f6847,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ެ
cockroach.streamid: 1
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=ce124e30,n2] querying next range at /Table/64/1/1
  [txn=ce124e30,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=ce124e30,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 582µs
   === SPAN START: [async] drain ===
  [n2] accumulation complete
  [n2] Consumer sent handshake. Consuming flow scheduled: false
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2411] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:45.224887 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:45.424052 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:45.597408 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2422] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2422] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=379e0a06,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=379e0a06,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=379e0a06,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=cba0f508,n2] querying next range at /Table/64/1/1
  [txn=cba0f508,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=cba0f508,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 459µs
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
  [n2] accumulation complete
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޻
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2423] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:46.503518 1751 server/status/runtime.go:433  [n2] runtime stats: 882 MiB RSS, 628 goroutines, 42 MiB/20 MiB/82 MiB GO alloc/idle/total, 109 MiB/147 MiB CGO alloc/total, 1760.97cgo/sec, 0.69/0.02 %(u/s)time, 0.01 %gc (5x)
I180818 06:14:46.597767 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:46.686484 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:46.844361 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2434] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2434] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=04e8e117,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=04e8e117,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=04e8e117,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.streamid: 1
cockroach.stat.outbox.bytes_sent: ߉
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=34dc3144,n2] querying next range at /Table/64/1/1
  [txn=34dc3144,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=34dc3144,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 306µs
  [n2] accumulation complete
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2] Consumer sent handshake. Consuming flow scheduled: true
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2435] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:47.677356 1753 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180818 06:14:47.844754 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:48.108378 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:48.221034 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2446] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2446] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=fe86fb4e,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=fe86fb4e,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=fe86fb4e,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ު
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 1µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=5e6f371f,n2] querying next range at /Table/64/1/1
  [txn=5e6f371f,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=5e6f371f,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
   === SPAN START: flow ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 329µs
  [n2] accumulation complete
  [n2] Consumer sent handshake. Consuming flow scheduled: true
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2447] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:48.547322 2321 server/status/runtime.go:433  [n3] runtime stats: 882 MiB RSS, 629 goroutines, 44 MiB/18 MiB/82 MiB GO alloc/idle/total, 109 MiB/147 MiB CGO alloc/total, 1735.20cgo/sec, 0.70/0.02 %(u/s)time, 0.01 %gc (5x)
I180818 06:14:49.223670 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:49.343423 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:49.585463 2339 server/status/recorder.go:652  [n3,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180818 06:14:49.707390 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2458] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2458] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=2d954465,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=2d954465,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=2d954465,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޻
cockroach.streamid: 1
   === SPAN START: [async] drain ===
  [n2] Consumer sent handshake. Consuming flow scheduled: false
   === SPAN START: table reader ===
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 5µs
cockroach.processorid: 0
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=7944cf97,n2] querying next range at /Table/64/1/1
  [txn=7944cf97,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=7944cf97,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 349µs
  [n2] accumulation complete
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2459] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:50.707745 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 2 AND a < 3
I180818 06:14:50.862564 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 3 AND a < 4
I180818 06:14:51.003332 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 3 AND a < 4
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2470] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2470] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=99faca61,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=99faca61,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=99faca61,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/3
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 1µs
  [n3] Scan /Table/64/1/3{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=260f0b6d,n3] querying next range at /Table/64/1/3
  [txn=260f0b6d,n3] r121: sending batch 1 Scan to (n3,s3):1
  [txn=260f0b6d,n3] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r121/1:/Table/64/1/{3-4}] read-only path
  [n3,s3,r121/1:/Table/64/1/{3-4}] command queue
  [n3,s3,r121/1:/Table/64/1/{3-4}] waiting for read lock
  [n3,s3,r121/1:/Table/64/1/{3-4}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 305µs
cockroach.processorid: 1
  [n3] accumulation complete
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ߆
cockroach.streamid: 1
   === SPAN START: [async] drain ===
  [n3] Consumer sent handshake. Consuming flow scheduled: false
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n3] Consumer sent handshake. Consuming flow scheduled: true
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2471] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:52.005136 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 2 AND a < 3
I180818 06:14:52.105095 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 3 AND a < 4
I180818 06:14:52.310994 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n3: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 3 AND a < 4
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2482] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2482] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 3) AND (a < 4) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=6239911a,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=6239911a,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=6239911a,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/3
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޹
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 1µs
cockroach.processorid: 0
  [n3] Scan /Table/64/1/3{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=c3ae13f2,n3] querying next range at /Table/64/1/3
  [txn=c3ae13f2,n3] r121: sending batch 1 Scan to (n3,s3):1
  [txn=c3ae13f2,n3] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n3] 1 Scan
  [n3,s3] executing 1 requests
  [n3,s3,r121/1:/Table/64/1/{3-4}] read-only path
  [n3,s3,r121/1:/Table/64/1/{3-4}] command queue
  [n3,s3,r121/1:/Table/64/1/{3-4}] waiting for read lock
  [n3,s3,r121/1:/Table/64/1/{3-4}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 357µs
  [n3] accumulation complete
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2483] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:52.580755 1255 server/status/runtime.go:433  [n1] runtime stats: 883 MiB RSS, 618 goroutines, 47 MiB/16 MiB/82 MiB GO alloc/idle/total, 108 MiB/149 MiB CGO alloc/total, 1754.39cgo/sec, 0.72/0.02 %(u/s)time, 0.01 %gc (5x)
I180818 06:14:52.595929 1252 gossip/gossip.go:538  [n1] gossip status (ok, 3 nodes)
gossip client (0/3 cur/max conns)
gossip server (2/3 cur/max conns, infos 2362/606 sent/received, bytes 3916976B/200940B sent/received)
  2: 127.0.0.1:40287 (2m56s)
  3: 127.0.0.1:39225 (2m54s)
I180818 06:14:52.844314 1257 server/status/recorder.go:652  [n1,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180818 06:14:53.311354 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a > 4
I180818 06:14:53.520608 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:53.845748 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:54.100209 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2500] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2500] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=f05d93c8,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=f05d93c8,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=f05d93c8,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޺
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 1µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=22c3c3ce,n2] querying next range at /Table/64/1/1
  [txn=22c3c3ce,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=22c3c3ce,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.stalltime: 283µs
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
  [n2] accumulation complete
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2] Consumer sent handshake. Consuming flow scheduled: false
  [n2] Consumer sent handshake. Consuming flow scheduled: true
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2501] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:55.100637 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:55.450523 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:55.642399 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2512] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2512] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=a68aaf6c,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=a68aaf6c,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=a68aaf6c,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ߁
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
cockroach.processorid: 0
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=9e977c9f,n2] querying next range at /Table/64/1/1
  [n2] Consumer sent handshake. Consuming flow scheduled: false
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2] Consumer sent handshake. Consuming flow scheduled: true
  [txn=9e977c9f,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=9e977c9f,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 295µs
cockroach.processorid: 1
  [n2] accumulation complete
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2513] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:56.486903 1890 gossip/gossip.go:538  [n2] gossip status (ok, 3 nodes)
gossip client (1/3 cur/max conns)
  1: 127.0.0.1:42135 (3m0s: infos 289/1323 sent/received, bytes 91040B/2227055B sent/received)
gossip server (0/3 cur/max conns, infos 289/1323 sent/received, bytes 91040B/2227055B sent/received)
I180818 06:14:56.520993 1751 server/status/runtime.go:433  [n2] runtime stats: 882 MiB RSS, 618 goroutines, 45 MiB/17 MiB/82 MiB GO alloc/idle/total, 109 MiB/149 MiB CGO alloc/total, 1716.00cgo/sec, 0.74/0.02 %(u/s)time, 0.01 %gc (5x)
I180818 06:14:56.647266 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:56.785246 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2518] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2518] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=69135466,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=69135466,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=69135466,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ߄
cockroach.streamid: 1
   === SPAN START: table reader ===
cockroach.stat.tablereader.stalltime: 2µs
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
   === SPAN START: [async] drain ===
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=6ef1d24a,n2] querying next range at /Table/64/1/1
  [txn=6ef1d24a,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=6ef1d24a,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.processorid: 1
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 402µs
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n2] Consumer sent handshake. Consuming flow scheduled: false
  [n2] Consumer sent handshake. Consuming flow scheduled: true
  [n2] accumulation complete
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2519] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:57.677294 1753 server/status/recorder.go:652  [n2,summaries] available memory from cgroups (8.0 EiB) exceeds system memory 16 GiB, using system memory
I180818 06:14:57.785686 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a < 1
I180818 06:14:57.842451 16028 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
I180818 06:14:58.167353 16028 ccl/partitionccl/partition_test.go:1156  SucceedsSoon: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
full trace:
   === SPAN START: session recording ===
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2530] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
   === SPAN START: sql txn ===
  [n1,client=127.0.0.1:50354,user=root] [Open pos:2530] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] r7: sending batch 1 Get to (n1,s1):1
  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n1] 1 Get
  [n1,s1] executing 1 requests
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>

  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
  [n1,client=127.0.0.1:50354,user=root] planning ends
  [n1,client=127.0.0.1:50354,user=root] checking distributability
  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
   === SPAN START: consuming rows ===
  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
   === SPAN START: outbox ===
cockroach.stat.outbox.bytes_sent: ޺
cockroach.streamid: 1
   === SPAN START: [async] drain ===
   === SPAN START: table reader ===
cockroach.processorid: 0
cockroach.stat.tablereader.input.rows: 0
cockroach.stat.tablereader.stalltime: 2µs
  [n2] Scan /Table/64/1/1{-/#}
   === SPAN START: txn coordinator send ===
   === SPAN START: dist sender send ===
  [txn=098f018e,n2] querying next range at /Table/64/1/1
  [txn=098f018e,n2] r89: sending batch 1 Scan to (n2,s2):2
  [txn=098f018e,n2] sending request to local server
   === SPAN START: /cockroach.roachpb.Internal/Batch ===
  [n2] 1 Scan
  [n2,s2] executing 1 requests
  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
   === SPAN START: ordered aggregator ===
cockroach.stat.aggregator.input.rows: 0
cockroach.stat.aggregator.mem.max: 10 KiB
cockroach.stat.aggregator.stalltime: 262µs
cockroach.processorid: 1
  [n2] accumulation complete
   === SPAN START: flow ===
  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
   === SPAN START: noop ===
cockroach.processorid: 2
  [n1,client=127.0.0.1:50354,user=root] execution ends
  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
   === SPAN START: txn coordinator send ===
  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2531] executing ExecStmt: SET TRACING = off
  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
I180818 06:14:58.382948 2318 gossip/gossip.go:538  [n3] gossip status (ok, 3 nodes)
gossip client (1/3 cur/max conns)
  1: 127.0.0.1:42135 (3m1s: infos 329/1067 sent/received, bytes 111328B/1695161B sent/received)
gossip server (0/3 cur/max conns, infos 329/1067 sent/received, bytes 111328B/1695161B sent/received)
I180818 06:14:58.556492 2321 server/status/runtime.go:433  [n3] runtime stats: 882 MiB RSS, 618 goroutines, 45 MiB/18 MiB/82 MiB GO alloc/idle/total, 108 MiB/149 MiB CGO alloc/total, 1761.98cgo/sec, 0.74/0.02 %(u/s)time, 0.01 %gc (5x)
    --- FAIL: TestInitialPartitioning/sparse_single_col_range_partitioning (48.37s)
    	soon.go:49: condition failed to evaluate within 45s: expected to scan on n2: SELECT count(*) FROM "sparse single col range partitioning" WHERE a >= 1 AND a < 2
    		[n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
    		full trace:
    		   === SPAN START: session recording ===
    		  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2530] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
    		  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: NoTxn
    		   === SPAN START: sql txn ===
    		  [n1,client=127.0.0.1:50354,user=root] [Open pos:2530] executing ExecStmt: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2)
    		  [n1,client=127.0.0.1:50354,user=root] executing: SELECT count(*) FROM "sparse single col range partitioning" WHERE (a >= 1) AND (a < 2) in state: Open
    		  [n1,client=127.0.0.1:50354,user=root] planning starts: SELECT
    		  [n1,client=127.0.0.1:50354,user=root] generating optimizer plan
    		   === SPAN START: txn coordinator send ===
    		   === SPAN START: dist sender send ===
    		  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] querying next range at /Table/2/1/52/"sparse single col range partitioning"/3/1
    		  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] r7: sending batch 1 Get to (n1,s1):1
    		  [client=127.0.0.1:50354,user=root,txn=0fd0d020,n1] sending request to local server
    		   === SPAN START: /cockroach.roachpb.Internal/Batch ===
    		  [n1] 1 Get
    		  [n1,s1] executing 1 requests
    		  [n1,s1,r7/1:/Table/{SystemCon…-11}] read-only path
    		  [n1,s1,r7/1:/Table/{SystemCon…-11}] command queue
    		  [n1,s1,r7/1:/Table/{SystemCon…-11}] waiting for read lock
    		  [n1,s1,r7/1:/Table/{SystemCon…-11}] read completed
    		   === SPAN START: txn coordinator send ===
    		  [n1,client=127.0.0.1:50354,user=root] client.Txn did AutoCommit. err: <nil>
    		
    		  [n1,client=127.0.0.1:50354,user=root] added table 'data.public."sparse single col range partitioning"' to table collection
    		  [n1,client=127.0.0.1:50354,user=root] optimizer plan succeeded
    		  [n1,client=127.0.0.1:50354,user=root] planning ends
    		  [n1,client=127.0.0.1:50354,user=root] checking distributability
    		  [n1,client=127.0.0.1:50354,user=root] distributable plan: true
    		  [n1,client=127.0.0.1:50354,user=root] execution starts: distributed
    		   === SPAN START: consuming rows ===
    		  [n1,client=127.0.0.1:50354,user=root] creating DistSQL plan with distributedMode=true
    		  [n1,client=127.0.0.1:50354,user=root] querying next range at /Table/64/1/1
    		  [n1,client=127.0.0.1:50354,user=root] running DistSQL plan
    		   === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
    		   === SPAN START: outbox ===
    		cockroach.stat.outbox.bytes_sent: ޺
    		cockroach.streamid: 1
    		   === SPAN START: [async] drain ===
    		   === SPAN START: table reader ===
    		cockroach.processorid: 0
    		cockroach.stat.tablereader.input.rows: 0
    		cockroach.stat.tablereader.stalltime: 2µs
    		  [n2] Scan /Table/64/1/1{-/#}
    		   === SPAN START: txn coordinator send ===
    		   === SPAN START: dist sender send ===
    		  [txn=098f018e,n2] querying next range at /Table/64/1/1
    		  [txn=098f018e,n2] r89: sending batch 1 Scan to (n2,s2):2
    		  [txn=098f018e,n2] sending request to local server
    		   === SPAN START: /cockroach.roachpb.Internal/Batch ===
    		  [n2] 1 Scan
    		  [n2,s2] executing 1 requests
    		  [n2,s2,r89/2:/Table/64/1/{1-2}] read-only path
    		  [n2,s2,r89/2:/Table/64/1/{1-2}] command queue
    		  [n2,s2,r89/2:/Table/64/1/{1-2}] waiting for read lock
    		  [n2,s2,r89/2:/Table/64/1/{1-2}] read completed
    		   === SPAN START: ordered aggregator ===
    		cockroach.stat.aggregator.input.rows: 0
    		cockroach.stat.aggregator.mem.max: 10 KiB
    		cockroach.stat.aggregator.stalltime: 262µs
    		cockroach.processorid: 1
    		  [n2] accumulation complete
    		   === SPAN START: flow ===
    		  [n1,client=127.0.0.1:50354,user=root] starting (1 processors, 0 startables)
    		   === SPAN START: noop ===
    		cockroach.processorid: 2
    		  [n1,client=127.0.0.1:50354,user=root] execution ends
    		  [n1,client=127.0.0.1:50354,user=root] rows affected: 1
    		   === SPAN START: txn coordinator send ===
    		  [n1,client=127.0.0.1:50354,user=root] AutoCommit. err: <nil>
    		  [n1,client=127.0.0.1:50354,user=root] releasing 1 tables
    		  [n1,client=127.0.0.1:50354,user=root] [NoTxn pos:2531] executing ExecStmt: SET TRACING = off
    		  [n1,client=127.0.0.1:50354,user=root] executing: SET TRACING = off in state: NoTxn
    		goroutine 16028 [running]:
    		runtime/debug.Stack(0xa7a358200, 0xc4215843f0, 0x3da27e0)
    			/usr/local/go/src/runtime/debug/stack.go:24 +0xb5
    		github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x3e03c80, 0xc42375e4b0, 0xc423bd1fb0)
    			/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:50 +0x172
    		github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc42375e4b0)
    			/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1156 +0x258
    		testing.tRunner(0xc42375e4b0, 0xc42110c540)
    			/usr/local/go/src/testing/testing.go:777 +0x16e
    		created by testing.(*T).Run
    			/usr/local/go/src/testing/testing.go:824 +0x565
@cockroach-teamcity cockroach-teamcity added this to the 2.1 milestone Aug 18, 2018
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Aug 18, 2018
@cockroach-teamcity
Copy link
Member Author

SHA: https://github.com/cockroachdb/cockroach/commits/88fd66dea46c2fbdb24c3f225a817ea806808ffa

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=847351&tab=buildLog

@cockroach-teamcity
Copy link
Member Author

SHA: https://github.com/cockroachdb/cockroach/commits/c74df43ba18345c48c685e899e2f4ef9785aef34

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=848724&tab=buildLog

@cockroach-teamcity
Copy link
Member Author

SHA: https://github.com/cockroachdb/cockroach/commits/c74df43ba18345c48c685e899e2f4ef9785aef34

Parameters:

TAGS=
GOFLAGS=-race

Failed test: https://teamcity.cockroachdb.com/viewLog.html?buildId=849178&tab=buildLog

This was referenced Aug 20, 2018
Closed
Closed
Closed
Closed
Closed
Closed
a-robinson added a commit to a-robinson/cockroach that referenced this issue Aug 20, 2018
@a-robinson
partitionccl: Skip flaky partitioning tests
41cf11c 
cc cockroachdb#28789 and cockroachdb#28786

Release note: None
@a-robinson a-robinson mentioned this issue Aug 20, 2018
Merged
craig bot pushed a commit that referenced this issue Aug 20, 2018
@knz @a-robinson
Merge #28814 #28863
cdd515c 
28814: sql: remove the broken support for BIT r=knz a=knz

Part of #28690.

This is a prior PR to #28807. I foresee that the other PR will need some iteration (and perhaps some consensus gathering) and may merge later in the 2.2 cycle. In the meantime we need to remove the brokenness from client apps. This PR disables the BIT type (in a backward-compatible manner!) until we can actually address #20991.

-----


Previously CockroachDB was handling the keyword BIT as an alias for
INT (specifically: INT with a "visible type" of BIT). With regards to
storing values, performing arithmetic, comparisons, etc, "BIT" values
were considered just integers.

In the PostgreSQL dialect however, bit arrays are a completely
different thing: they are arbitrary long strings of bits, possibly
longer (or shorter) than 64 bits, with odd number of bits, etc. They
use different literal formats, have different semantics for arithmetic
and concatenation, etc.

Unfortunately, this mismatch confuses clients that either want to use
the pg BIT semantics, or do introspection (e.g. ORMs).

To prevent this confusion, this patch removes the broken support for
BIT until proper support is actually introduced. Now clients that
attempt to use the BIT keyword will see an unimplemented feature error
linking back to issue #20991. As uninmplemented errors are also
reported, we will be able to track demand for it.

Release note (backward-incompatible change): CockroachDB previously
included some preliminary support for the data type
"BIT". Unfortunately this functionality was both incorrectly
implemented and was found to cause incompatibility with client
apps. It is thus removed; it will be replaced by a
PostgreSQL-compatible replacement at a later time.

Release note (sql change): Tables columns created prior to this patch
with the type name "BIT" will continue to work but will see their type
automatically changed to INT in the output of SHOW TABLES,
`information_schema`, etc. This is backward-compatible insofar that
the previous BIT type in CockroachDB was actually a simple
integer. Only the name of the type of these columns changes; their
values are unaffected and can continue to be used in queries without
visible changes to query results in client apps which actually
utilized the incorrect pre-2.1 BIT semantics.

28863: partitionccl: Skip flaky partitioning tests r=a-robinson a=a-robinson

cc #28789 and #28786

Release note: None

These have been failing like crazy the last few days. We should of course fix them, but I'm tired of seeing new issues filed about them every few hours.

Co-authored-by: Raphael 'kena' Poss <knz@cockroachlabs.com>
Co-authored-by: Alex Robinson <alexdwanerobinson@gmail.com>
@tbg tbg assigned danhhz and unassigned benesch Aug 21, 2018
@tbg tbg added the A-cdc Change Data Capture label Aug 21, 2018
@danhhz danhhz added A-partitioning and removed A-cdc Change Data Capture labels Sep 6, 2018
@danhhz
Copy link
Contributor

danhhz commented Oct 8, 2018

Did a bit of initial triage to check if this was still an issue. Found a panic in BitArray.Format (#31115) and then managed to get TestInitialPartitioning/single_col_list_partitioning_-_DEFAULT to timeout after 8 minutes.

There were all sorts of the following in the logs

E181008 22:21:01.078721 24713 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot 08b9f4fe at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n2,s2,r40/3:/{Table/57/1/5-Max}]

I think the SELECT * run by (*partitioningTest).verifyScansFn was stuck in waiting on a prereq for 7 minutes when the test timed out. Presumably deadlocked because of the above?

goroutine 1552 [select, 7 minutes]:
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).beginCmds(0xc4235c8000, 0x2ecfba0, 0xc421370390, 0xc42130a300, 0xc4217f6c00, 0x2, 0x8, 0xc4229e3100)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:2399 +0x683
github.com/cockroachdb/cockroach/pkg/storage.(*Replica).executeReadOnlyBatch(0xc4235c8000, 0x2ecfba0, 0xc421370390, 0x155bc1cdff721727, 0x0, 0x100000001, 0x1, 0x29, 0x0, 0xc4208e7400, ...)
	/go/src/github.com/cockroachdb/cockroach/pkg/storage/replica.go:3066 +0x250
...

Here's (hopefully) an interesting prefix of the test logs

=== RUN   TestInitialPartitioning/single_col_list_partitioning_-_DEFAULT
I181008 22:13:08.001211 1552 sql/event_log.go:126  [n1,client=127.0.0.1:46526,user=root] Event: "create_table", target: 57, info: {TableName:data.public."single col list partitioning - DEFAULT" Statement:CREATE TABLE "single col list partitioning - DEFAULT" (a INT PRIMARY KEY) PARTITION BY LIST (a) (PARTITION p4 VALUES IN (4), PARTITION p5 VALUES IN (5), PARTITION pd VALUES IN (DEFAULT)) User:root}
I181008 22:13:08.002867 15594 storage/replica_command.go:298  [n1,split,s1,r37/1:/{Table/56/2-Max}] initiating a split of this range at key /Table/57 [r38]
I181008 22:13:08.015852 997 storage/replica_proposal.go:211  [n3,s3,r37/2:/Table/5{6/2-7}] new range lease repl=(n3,s3):2 seq=3 start=1539036788.012250849,0 epo=1 pro=1539036788.012253331,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:08.017625 15715 storage/replica_command.go:812  [n3,replicate,s3,r37/2:/Table/5{6/2-7}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r37:/Table/5{6/2-7} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=1]
E181008 22:13:08.025558 15701 storage/queue.go:791  [n1,replicate,s1,r38/1:/{Table/57-Max}] no removable replicas from range that needs a removal: [raft progress unknown]
I181008 22:13:08.029133 15719 storage/store_snapshot.go:615  [n3,raftsnapshot,s3,r37/2:/Table/5{6/2-7}] sending Raft snapshot 8c656cd3 at applied index 17
I181008 22:13:08.031630 15719 storage/store_snapshot.go:657  [n3,raftsnapshot,s3,r37/2:/Table/5{6/2-7}] streamed snapshot to (n2,s2):3: kv pairs: 8, log entries: 7, rate-limit: 8.0 MiB/sec, 7ms
I181008 22:13:08.031861 15731 storage/replica_raftstorage.go:803  [n2,s2,r37/3:{-}] applying Raft snapshot at index 17 (id=8c656cd3, encoded size=3039, 1 rocksdb batches, 7 log entries)
I181008 22:13:08.032096 15731 storage/replica_raftstorage.go:809  [n2,s2,r37/3:/Table/5{6/2-7}] applied Raft snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181008 22:13:08.032890 1552 sql/event_log.go:126  [n1,client=127.0.0.1:46526,user=root] Event: "set_zone_config", target: 57, info: {Target:data."single col list partitioning - DEFAULT".p4 Config: Options:constraints = '[+n2]' User:root}
I181008 22:13:08.035281 14396 storage/replica_command.go:298  [n1,split,s1,r38/1:/{Table/57-Max}] initiating a split of this range at key /Table/57/1/4 [r39]
I181008 22:13:08.040300 15715 storage/replica.go:3899  [n3,s3,r37/2:/Table/5{6/2-7}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):3 (n3,s3):2] next=4
I181008 22:13:08.049846 1176 storage/store.go:3800  [n1,s1,r37/1:/Table/5{6/2-7}] added to replica GC queue (peer suggestion)
I181008 22:13:08.050541 15751 storage/replica_command.go:298  [n1,split,s1,r39/1:/{Table/57/1/4-Max}] initiating a split of this range at key /Table/57/1/5 [r40]
I181008 22:13:08.051141 770 storage/replica_proposal.go:211  [n2,s2,r37/3:/Table/5{6/2-7}] new range lease repl=(n2,s2):3 seq=4 start=1539036788.047954251,0 epo=1 pro=1539036788.047958475,0 following repl=(n3,s3):2 seq=3 start=1539036788.012250849,0 epo=1 pro=1539036788.012253331,0
I181008 22:13:08.052648 15658 storage/store_snapshot.go:615  [n1,raftsnapshot,s1,r38/1:/Table/57{-/1/4}] sending Raft snapshot 64c9e0a2 at applied index 16
I181008 22:13:08.053059 15643 storage/replica_command.go:812  [n1,replicate,s1,r38/1:/Table/57{-/1/4}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r38:/Table/57{-/1/4} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=1]
I181008 22:13:08.053322 15658 storage/store_snapshot.go:657  [n1,raftsnapshot,s1,r38/1:/Table/57{-/1/4}] streamed snapshot to (n2,s2):3: kv pairs: 8, log entries: 6, rate-limit: 8.0 MiB/sec, 1ms
I181008 22:13:08.053873 1552 sql/event_log.go:126  [n1,client=127.0.0.1:46526,user=root] Event: "set_zone_config", target: 57, info: {Target:data."single col list partitioning - DEFAULT".p5 Config: Options:constraints = '[+n3]' User:root}
I181008 22:13:08.054379 15661 storage/replica_raftstorage.go:803  [n2,s2,r38/3:{-}] applying Raft snapshot at index 16 (id=64c9e0a2, encoded size=2890, 1 rocksdb batches, 6 log entries)
I181008 22:13:08.054409 1176 storage/store.go:3800  [n1,s1,r37/1:/Table/5{6/2-7}] added to replica GC queue (peer suggestion)
I181008 22:13:08.054702 15661 storage/replica_raftstorage.go:809  [n2,s2,r38/3:/Table/57{-/1/4}] applied Raft snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181008 22:13:08.054795 15662 storage/replica_command.go:812  [n2,replicate,s2,r37/3:/Table/5{6/2-7}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r37:/Table/5{6/2-7} [(n2,s2):3, (n3,s3):2, next=4, gen=1]
I181008 22:13:08.058876 15697 storage/store.go:2741  [n1,replicaGC,s1,r37/1:/Table/5{6/2-7}] removing replica r37/1
I181008 22:13:08.059124 15697 storage/replica.go:878  [n1,replicaGC,s1,r37/1:/Table/5{6/2-7}] removed 6 (0+6) keys in 0ms [clear=0ms commit=0ms]
I181008 22:13:08.065102 15729 storage/replica_command.go:298  [n1,split,s1,r40/1:/{Table/57/1/5-Max}] initiating a split of this range at key /Table/57/1/6 [r41]
I181008 22:13:08.067434 15755 storage/store_snapshot.go:615  [n1,raftsnapshot,s1,r39/1:/Table/57/1/{4-5}] sending Raft snapshot 328b600d at applied index 11
I181008 22:13:08.075294 15755 storage/store_snapshot.go:657  [n1,raftsnapshot,s1,r39/1:/Table/57/1/{4-5}] streamed snapshot to (n2,s2):3: kv pairs: 6, log entries: 1, rate-limit: 8.0 MiB/sec, 13ms
I181008 22:13:08.077789 15783 storage/replica_raftstorage.go:803  [n2,s2,r39/3:{-}] applying Raft snapshot at index 11 (id=328b600d, encoded size=320, 1 rocksdb batches, 1 log entries)
I181008 22:13:08.078138 15783 storage/replica_raftstorage.go:809  [n2,s2,r39/3:/{Table/57/1/4-Max}] applied Raft snapshot in 0ms [clear=0ms batch=0ms entries=0ms commit=0ms]
I181008 22:13:08.079192 15643 storage/replica.go:3899  [n1,s1,r38/1:/Table/57{-/1/4}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n2,s2):3] next=4
E181008 22:13:08.079602 15771 storage/queue.go:791  [n1,raftsnapshot,s1,r40/1:/{Table/57/1/5-Max}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot f7de22ec at applied index 14 with error: [n2,s2],r40: cannot apply snapshot: snapshot intersects existing range [n2,s2,r39/3:/{Table/57/1/4-Max}]
I181008 22:13:08.080831 15759 storage/replica_command.go:812  [n1,replicate,s1,r38/1:/Table/57{-/1/4}] change replicas (REMOVE_REPLICA (n2,s2):3): read existing descriptor r38:/Table/57{-/1/4} [(n1,s1):1, (n2,s2):3, next=4, gen=1]
I181008 22:13:08.084529 1181 storage/store.go:3800  [n3,s3,r38/2:/Table/57{-/1/4}] added to replica GC queue (peer suggestion)
I181008 22:13:08.084599 1181 storage/store.go:3800  [n3,s3,r38/2:/Table/57{-/1/4}] added to replica GC queue (peer suggestion)
I181008 22:13:08.086332 15776 storage/store.go:2741  [n3,replicaGC,s3,r38/2:/Table/57{-/1/4}] removing replica r38/2
I181008 22:13:08.086655 15776 storage/replica.go:878  [n3,replicaGC,s3,r38/2:/Table/57{-/1/4}] removed 6 (0+6) keys in 0ms [clear=0ms commit=0ms]
I181008 22:13:08.119693 15759 storage/replica.go:3899  [n1,s1,r38/1:/Table/57{-/1/4}] proposing REMOVE_REPLICA((n2,s2):3): updated=[(n1,s1):1] next=4
I181008 22:13:08.121761 1552 sql/event_log.go:126  [n1,client=127.0.0.1:46526,user=root] Event: "set_zone_config", target: 57, info: {Target:data."single col list partitioning - DEFAULT".pd Config: Options:constraints = '[+n1]' User:root}
I181008 22:13:08.121995 15685 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "single col list partitioning - DEFAULT" WHERE a < 4
I181008 22:13:08.123351 15713 storage/replica_command.go:298  [n1,split,s1,r41/1:/{Table/57/1/6-Max}] initiating a split of this range at key /Table/57/2 [r42]
I181008 22:13:08.123616 15712 storage/replica_command.go:298  [n1,split,s1,r38/1:/Table/57{-/1/4}] initiating a split of this range at key /Table/57/1 [r43]
I181008 22:13:08.124341 800 storage/replica_proposal.go:211  [n2,s2,r39/3:/Table/57/1/{4-5}] new range lease repl=(n2,s2):3 seq=3 start=1539036788.120902810,0 epo=1 pro=1539036788.120905300,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:08.124352 1129 storage/store.go:3800  [n2,s2,r38/3:/Table/57{-/1/4}] added to replica GC queue (peer suggestion)
I181008 22:13:08.127665 15801 storage/store.go:2741  [n2,replicaGC,s2,r38/3:/Table/57{-/1/4}] removing replica r38/3
I181008 22:13:08.127910 15801 storage/replica.go:878  [n2,replicaGC,s2,r38/3:/Table/57{-/1/4}] removed 7 (0+7) keys in 0ms [clear=0ms commit=0ms]
I181008 22:13:08.128065 15829 storage/replica_command.go:812  [n1,replicate,s1,r40/1:/Table/57/1/{5-6}] change replicas (REMOVE_REPLICA (n2,s2):3): read existing descriptor r40:/Table/57/1/{5-6} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=1]
E181008 22:13:08.132697 15816 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/{Table/57/1/6-Max}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot 533a06d2 at applied index 10 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range [n2,s2,r40/3:/{Table/57/1/5-Max}]
I181008 22:13:08.138844 15662 storage/replica.go:3899  [n2,s2,r37/3:/Table/5{6/2-7}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n2,s2):3] next=4
I181008 22:13:08.140319 15685 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "single col list partitioning - DEFAULT" WHERE a = 4
I181008 22:13:08.140800 15829 storage/replica.go:3899  [n1,s1,r40/1:/Table/57/1/{5-6}] proposing REMOVE_REPLICA((n2,s2):3): updated=[(n1,s1):1 (n3,s3):2] next=4
I181008 22:13:08.147171 1016 storage/replica_proposal.go:211  [n3,s3,r40/2:/Table/57/1/{5-6}] new range lease repl=(n3,s3):2 seq=3 start=1539036788.143523819,0 epo=1 pro=1539036788.143526975,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:08.147543 15744 storage/replica_command.go:812  [n1,replicate,s1,r41/1:/Table/57/{1/6-2}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r41:/Table/57/{1/6-2} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=1]
I181008 22:13:08.150677 1605 storage/store.go:3800  [n3,s3,r37/2:/Table/5{6/2-7}] added to replica GC queue (peer suggestion)
I181008 22:13:08.159112 15924 storage/replica_command.go:812  [n3,replicate,s3,r40/2:/Table/57/1/{5-6}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r40:/Table/57/1/{5-6} [(n1,s1):1, (n3,s3):2, next=4, gen=1]
I181008 22:13:08.161323 15685 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "single col list partitioning - DEFAULT" WHERE a = 5
I181008 22:13:08.169109 15744 storage/replica.go:3899  [n1,s1,r41/1:/Table/57/{1/6-2}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n1,s1):1 (n2,s2):3] next=4
I181008 22:13:08.173853 15685 ccl/partitionccl/partition_test.go:200  query: SELECT count(*) FROM "single col list partitioning - DEFAULT" WHERE a > 5
I181008 22:13:08.173861 15939 storage/replica_command.go:812  [n1,replicate,s1,r41/1:/Table/57/{1/6-2}] change replicas (REMOVE_REPLICA (n2,s2):3): read existing descriptor r41:/Table/57/{1/6-2} [(n1,s1):1, (n2,s2):3, next=4, gen=1]
I181008 22:13:08.176558 1181 storage/store.go:3800  [n3,s3,r41/2:/Table/57/{1/6-2}] added to replica GC queue (peer suggestion)
I181008 22:13:08.177125 1089 storage/store.go:3819  [n1,s1,r38/1:/Table/57{-/1}] added to replica GC queue (contacted deleted peer)
I181008 22:13:08.178650 1176 storage/store.go:3819  [n1,s1,r38/1:/Table/57{-/1}] added to replica GC queue (contacted deleted peer)
I181008 22:13:08.201037 15924 storage/replica.go:3899  [n3,s3,r40/2:/Table/57/1/{5-6}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n3,s3):2] next=4
I181008 22:13:08.208719 15825 storage/replica_command.go:812  [n2,replicate,s2,r39/3:/Table/57/1/{4-5}] change replicas (REMOVE_REPLICA (n1,s1):1): read existing descriptor r39:/Table/57/1/{4-5} [(n1,s1):1, (n3,s3):2, (n2,s2):3, next=4, gen=1]
I181008 22:13:08.216436 1176 storage/store.go:3800  [n1,s1,r40/1:/Table/57/1/{5-6}] added to replica GC queue (peer suggestion)
I181008 22:13:08.220108 15825 storage/replica.go:3899  [n2,s2,r39/3:/Table/57/1/{4-5}] proposing REMOVE_REPLICA((n1,s1):1): updated=[(n2,s2):3 (n3,s3):2] next=4
I181008 22:13:08.221872 1089 storage/store.go:3800  [n1,s1,r39/1:/Table/57/1/{4-5}] added to replica GC queue (peer suggestion)
I181008 22:13:08.221895 15986 storage/replica_command.go:812  [n2,replicate,s2,r39/3:/Table/57/1/{4-5}] change replicas (REMOVE_REPLICA (n3,s3):2): read existing descriptor r39:/Table/57/1/{4-5} [(n2,s2):3, (n3,s3):2, next=4, gen=1]
I181008 22:13:08.232726 15986 storage/replica.go:3899  [n2,s2,r39/3:/Table/57/1/{4-5}] proposing REMOVE_REPLICA((n3,s3):2): updated=[(n2,s2):3] next=4
I181008 22:13:08.234992 1605 storage/store.go:3800  [n3,s3,r39/2:/Table/57/1/{4-5}] added to replica GC queue (peer suggestion)
I181008 22:13:08.351834 1605 storage/store.go:3800  [n3,s3,r39/2:/Table/57/1/{4-5}] added to replica GC queue (peer suggestion)
I181008 22:13:08.380165 1089 storage/store.go:3800  [n1,s1,r39/1:/Table/57/1/{4-5}] added to replica GC queue (peer suggestion)
E181008 22:13:09.178690 15933 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot c044de57 at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range [n2,s2,r40/3:/{Table/57/1/5-Max}]
E181008 22:13:10.178808 16010 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot 1a031b78 at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range [n2,s2,r40/3:/{Table/57/1/5-Max}]
I181008 22:13:10.886217 772 storage/replica_proposal.go:211  [n2,s2,r11/3:/Table/1{4-5}] new range lease repl=(n2,s2):3 seq=3 start=1539036790.876340234,1 epo=1 pro=1539036790.884628123,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:10.947371 780 storage/replica_proposal.go:211  [n2,s2,r4/3:/System/{NodeLive…-tsd}] new range lease repl=(n2,s2):3 seq=3 start=1539036790.876340234,1 epo=1 pro=1539036790.945937960,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:10.978402 1129 storage/store.go:3800  [n2,s2,r40/3:/{Table/57/1/5-Max}] added to replica GC queue (peer suggestion)
I181008 22:13:10.978427 1583 storage/store.go:3800  [n2,s2,r40/3:/{Table/57/1/5-Max}] added to replica GC queue (peer suggestion)
E181008 22:13:11.179386 16154 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot a4a95d94 at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n2,s2,r40/3:/{Table/57/1/5-Max}]
I181008 22:13:11.880419 298 server/status/runtime.go:465  [n1] runtime stats: 223 MiB RSS, 651 goroutines, 40 MiB/4.5 MiB/67 MiB GO alloc/idle/total, 40 MiB/60 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (33x), 59 MiB/59 MiB (r/w)net
W181008 22:13:11.912926 300 server/node.go:886  [n1,summaries] health alerts detected: {Alerts:[{StoreID:1 Category:METRICS Description:queue.replicate.process.failure Value:260} {StoreID:1 Category:METRICS Description:queue.raftsnapshot.process.failure Value:8}]}
I181008 22:13:11.925907 233 storage/replica_proposal.go:211  [n1,s1,r5/1:/System/ts{d-e}] new range lease repl=(n1,s1):1 seq=3 start=1539036781.875476434,0 epo=1 pro=1539036791.925587043,0 following repl=(n1,s1):1 seq=2 start=1539036781.875476434,0 exp=1539036790.876340234,0 pro=1539036781.876362342,0
I181008 22:13:12.178796 820 server/status/runtime.go:465  [n2] runtime stats: 227 MiB RSS, 651 goroutines, 0 B/0 B/0 B GO alloc/idle/total, 41 MiB/62 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (34x), 60 MiB/60 MiB (r/w)net
E181008 22:13:12.182024 16163 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot f94f8e38 at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n2,s2,r40/3:/{Table/57/1/5-Max}]
I181008 22:13:12.252561 1042 server/status/runtime.go:465  [n3] runtime stats: 227 MiB RSS, 651 goroutines, 0 B/0 B/0 B GO alloc/idle/total, 41 MiB/62 MiB CGO alloc/total, 0.0 CGO/sec, 0.0/0.0 %(u/s)time, 0.0 %gc (34x), 59 MiB/59 MiB (r/w)net
E181008 22:13:13.079560 16173 storage/queue.go:791  [n1,raftsnapshot,s1,r41/1:/Table/57/{1/6-2}] snapshot failed: (n2,s2):3: remote couldn't accept Raft snapshot 9283a1c3 at applied index 19 with error: [n2,s2],r41: cannot apply snapshot: snapshot intersects existing range; initiated GC: [n2,s2,r40/3:/{Table/57/1/5-Max}]

@jordanlewis
Copy link
Member

I saw the snapshot intersects existing range thing in #31096 as well, I wonder if it's related?

@danhhz danhhz assigned tbg and unassigned danhhz Oct 17, 2018
@danhhz
Copy link
Contributor

danhhz commented Oct 17, 2018

Assigning to @tschottdorf for triage

@danhhz danhhz mentioned this issue Oct 17, 2018
Closed
@benesch benesch unassigned tbg Oct 22, 2018
@benesch benesch self-assigned this Oct 22, 2018
@tbg
Copy link
Member

tbg commented Dec 11, 2018

Long time no fail.

@tbg tbg closed this as completed Dec 11, 2018
@danhhz
Copy link
Contributor

danhhz commented Dec 11, 2018

Heh, because it's skipped. This really needs to be fixed. Essentially our entire test coverage of partitioning (this plus TestRepartitioning) is skipped.

@danhhz danhhz reopened this Dec 11, 2018
@tbg tbg changed the title ccl/partitionccl: TestInitialPartitioning failed under stress ccl/partitionccl: TestInitialPartitioning failed under stress [skipped] Dec 11, 2018
@tbg
Copy link
Member

tbg commented Dec 11, 2018

Ugh. Thanks for noticing.

@tbg tbg assigned petermattis and unassigned benesch Dec 19, 2018
@tbg
Copy link
Member

tbg commented Dec 19, 2018

@petermattis could you take a look at this?

@petermattis
Copy link
Collaborator

Looking. So far I'm unable to reproduce (and yes, I've unskipped the test). I did have to fix the test cases to avoid using ARRAY as an indexed column.

@petermattis
Copy link
Collaborator

Just didn't run long enough:

~ make stressrace PKG=./ccl/partitionccl/ TESTS=TestInitialPartitioning
...
8 runs completed, 1 failures, over 6m30s

@petermattis
Copy link
Collaborator

The failure I'm seeing is that verification that a scan is taking place on a particular node is not occurring. In particular, the test is failing this query for 45s:

E181229 20:45:39.080740 26116 ccl/partitionccl/partition_test.go:206 scan verification failed: expected to scan on n2: SELECT count(*) FROM "NAME" WHERE a = '4p<w':::STRING:::NAME

The logs shows that partitioning did split the table at the specified key (4p<w). Ok, this is interesting, I think the test has faulty failure detection:

E181229 20:45:39.080740 26116 ccl/partitionccl/partition_test.go:206  scan verification failed: expected to scan on n2: SELECT count(*) FROM "NAME" WHERE a = '4p<w':::STRING:::NAME
[n1,s1,r6/1:/Table/{SystemCon…-11}] read completed
full trace:
...
  [n1,s1,r6/1:/Table/{SystemCon…-11}] read completed
...
  [n2,s2,r245/2:/Table/87/1/"4p<w"{-/Pr…}] read completed
...

So the test is complaining that the scan did not complete on n2, but the full trace does show that a read completed on n2. The test is looking for a trace line that contains the phrase read completed and n2, but not taking into account that a query could be reading the system config to find the table descriptor. Not sure what the best course of action is here. I suppose I can just filter trace lines for r6 (which will always be the system config range in this test). Let's see if that de-flakes the test.

petermattis added a commit to petermattis/cockroach that referenced this issue Dec 29, 2018
@petermattis
ccl/partitionccl: re-enable Test{InitialPartitioning,Repartitioning}
dd2feee 
Avoid creating test cases with an `ARRAY` column as the primary
key. Unify the handling of non-indexable column types for test case
generation (`ARRAY`, `JSONB` and `TUPLE`).

Adjust `verifyScansOnNode` to skip `read completed` trace lines for the
system config range. Reads can be performed on this range to renew the
table lease and we want to ignore those reads for the purposes of the
test.

Fixes cockroachdb#28786
Fixes cockroachdb#28789

Release note: None
@petermattis petermattis mentioned this issue Dec 29, 2018
Merged
petermattis added a commit to petermattis/cockroach that referenced this issue Dec 31, 2018
@petermattis
ccl/partitionccl: re-enable Test{InitialPartitioning,Repartitioning}
34e00b1 
Avoid creating test cases with an `ARRAY` column as the primary
key. Unify the handling of non-indexable column types for test case
generation (`ARRAY`, `JSONB` and `TUPLE`).

Adjust `verifyScansOnNode` to skip `read completed` trace lines for the
system config range. Reads can be performed on this range to renew the
table lease and we want to ignore those reads for the purposes of the
test.

Fixes cockroachdb#28786
Fixes cockroachdb#28789

Release note: None
craig bot pushed a commit that referenced this issue Jan 1, 2019
@petermattis
Merge #33409
739b007 
33409: ccl/partitionccl: re-enable Test{InitialPartitioning,Repartitioning} r=benesch a=petermattis

Avoid creating test cases with an `ARRAY` column as the primary
key. Unify the handling of non-indexable column types for test case
generation (`ARRAY`, `JSONB` and `TUPLE`).

Adjust `verifyScansOnNode` to skip `read completed` trace lines for the
system config range. Reads can be performed on this range to renew the
table lease and we want to ignore those reads for the purposes of the
test.

Fixes #28786
Fixes #28789

Release note: None

Co-authored-by: Peter Mattis <petermattis@gmail.com>
craig bot pushed a commit that referenced this issue Jan 1, 2019
@petermattis
Merge #33409
a0217ed 
33409: ccl/partitionccl: re-enable Test{InitialPartitioning,Repartitioning} r=benesch a=petermattis

Avoid creating test cases with an `ARRAY` column as the primary
key. Unify the handling of non-indexable column types for test case
generation (`ARRAY`, `JSONB` and `TUPLE`).

Adjust `verifyScansOnNode` to skip `read completed` trace lines for the
system config range. Reads can be performed on this range to renew the
table lease and we want to ignore those reads for the purposes of the
test.

Fixes #28786
Fixes #28789

Release note: None

Co-authored-by: Peter Mattis <petermattis@gmail.com>
@craig craig bot closed this as completed in #33409 Jan 2, 2019
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@petermattis petermattis

Labels
A-partitioning C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
2.1
Development

No branches or pull requests
6 participants
@jordanlewis @danhhz @benesch @tbg @petermattis @cockroach-teamcity