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

teamcity: failed test: TestInitialPartitioning #41831

Closed
cockroach-teamcity opened this issue Oct 22, 2019 · 0 comments · Fixed by #41880
Closed

teamcity: failed test: TestInitialPartitioning #41831

cockroach-teamcity opened this issue Oct 22, 2019 · 0 comments · Fixed by #41880
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone
19.2

Comments

@cockroach-teamcity
Copy link
Member

The following tests appear to have failed on master (testrace): TestInitialPartitioning/varbit_table, TestInitialPartitioning/list-list_partitioning, TestInitialPartitioning/time_table, TestInitialPartitioning/inet_table, TestInitialPartitioning/collatedstring{de}_table, TestInitialPartitioning/bytes_table, TestInitialPartitioning/uuid_table, TestInitialPartitioning/string_table, TestInitialPartitioning

You may want to check for open issues.

#1553933:

TestInitialPartitioning/bytes_table
...44652,user=root] query cache hit
              [n1,client=127.0.0.1:44652,user=root] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/85/1/"\x00"
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 16.743ms
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.2 KiB
            cockroach.streamid: 1
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/85/{1/"\x00"-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=083d696e] querying next range at /Table/85/1/"\x00"
               === SPAN START: [async] drain ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2,txn=083d696e] r85: sending batch 1 Scan to (n2,s2):1
              [n2,txn=083d696e] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r85/1:/Table/85/{1/""/Pr…-2}] read-only path
              [n2,s2,r85/1:/Table/85/{1/""/Pr…-2}] acquire latches
              [n2,s2,r85/1:/Table/85/{1/""/Pr…-2}] waited 85.709µs to acquire latches
              [n2,s2,r85/1:/Table/85/{1/""/Pr…-2}] waiting for read lock
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,s2,r85/1:/Table/85/{1/""/Pr…-2}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 491µs
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:15786] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 937249 [running]:
            runtime/debug.Stack(0xc002828570, 0x6722640, 0xc003ea5c60)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc0016e8200, 0xc002828570)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc0016e8200)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc0016e8200, 0xc005eed050)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/uuid_table
...nt=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/88/1/"\xeb\xc5BQY/L\x9c\x9e\x17\xac\x8e\x183\x11h"
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 14.139ms
              [n2] starting scan with limitBatches true
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 KiB
            cockroach.streamid: 1
              [n2] Scan /Table/88/{1/"\xeb\xc5BQY/L\x9c\x9e\x17\xac\x8e\x183\x11h"-2}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=14dd336a] querying next range at /Table/88/1/"\xeb\xc5BQY/L\x9c\x9e\x17\xac\x8e\x183\x11h"
              [n2,txn=14dd336a] r260: sending batch 1 Scan to (n2,s2):1
              [n2,txn=14dd336a] sending request to local client
               === SPAN START: flow ===
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r260/1:/Table/88/{1/"\xeb…-2}] read-only path
              [n2,s2,r260/1:/Table/88/{1/"\xeb…-2}] acquire latches
              [n2,s2,r260/1:/Table/88/{1/"\xeb…-2}] waited 82.65µs to acquire latches
              [n2,s2,r260/1:/Table/88/{1/"\xeb…-2}] waiting for read lock
              [n2,s2,r260/1:/Table/88/{1/"\xeb…-2}] read completed
               === SPAN START: [async] drain ===
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 521µs
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:17637] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1092543 [running]:
            runtime/debug.Stack(0xc002b2c600, 0x6722640, 0xc0048d6560)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc004c24000, 0xc002b2c600)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004c24000)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004c24000, 0xc00518c210)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/inet_table
...] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/89/1
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.2 KiB
            cockroach.streamid: 1
               === SPAN START: [async] drain ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 3.644ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/89/1{-/"\x00\x10/x\xff\x1b"/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=d360af24] querying next range at /Table/89/1
              [n2,txn=d360af24] r263: sending batch 1 Scan to (n2,s2):1
              [n2,txn=d360af24] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
               === SPAN START: flow ===
              [n2,s2,r263/1:/Table/89/1{-/"\x00\…}] read-only path
              [n2,s2,r263/1:/Table/89/1{-/"\x00\…}] acquire latches
              [n2,s2,r263/1:/Table/89/1{-/"\x00\…}] waited 87.456µs to acquire latches
              [n2,s2,r263/1:/Table/89/1{-/"\x00\…}] waiting for read lock
              [n2,s2,r263/1:/Table/89/1{-/"\x00\…}] read completed
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2] Consumer sent handshake. Consuming flow scheduled: false
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 537µs
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:18170] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1148127 [running]:
            runtime/debug.Stack(0xc0043faa80, 0x6722640, 0xc0033e9280)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc0054ffa00, 0xc0043faa80)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc0054ffa00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc0054ffa00, 0xc0038347e0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/list-list_partitioning
...eta2/Table/71/1/5/NULL
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21,range-lookup=/Table/71/1/5] r1: sending batch 1 Scan to (n2,s2):3
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21,range-lookup=/Table/71/1/5] sending request to 127.0.0.1:45827
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r1/3:/{Min-System/NodeL…}] read-only path
              [n2,s2,r1/3:/{Min-System/NodeL…}] acquire latches
              [n2,s2,r1/3:/{Min-System/NodeL…}] operation accepts inconsistent results
              [n2,s2,r1/3:/{Min-System/NodeL…}] waiting for read lock
              [n2,s2,r1/3:/{Min-System/NodeL…}] submitting 1 intents to asynchronous processing
              [n2,s2,r1/3:/{Min-System/NodeL…}] read completed
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] looked up range descriptor: r160:/Table/71/1/5{-/6} [(n1,s1):1, (n3,s3):2, next=3, gen=125]
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] r160: sending batch 1 Scan to (n1,s1):1
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] 1 Scan
              [n1,s1] executing 1 requests
              [n1] *roachpb.RangeNotFoundError
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] application error: r160 was not found on s1
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] error: (err: r160 was not found on s1) <nil>; trying next peer (n3,s3):2
              [n1,client=127.0.0.1:44652,user=root,txn=988e7d21] sending request to 127.0.0.1:42761
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n3] 1 Scan
              [n3,s3] executing 1 requests
              [n3,s3,r160/2:/Table/71/1/5{-/6}] read-only path
              [n3,s3,r160/2:/Table/71/1/5{-/6}] acquire latches
              [n3,s3,r160/2:/Table/71/1/5{-/6}] waited 84.488µs to acquire latches
              [n3,s3,r160/2:/Table/71/1/5{-/6}] waiting for read lock
              [n3,s3,r160/2:/Table/71/1/5{-/6}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 871µs
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:7414] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 432136 [running]:
            runtime/debug.Stack(0xc005cd6390, 0x6722640, 0xc003910e00)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc005c66d00, 0xc005cd6390)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc005c66d00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc005c66d00, 0xc005fdc4e0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning
...pshot_queue.go:125  [n1,raftsnapshot,s1,r6/1:/Table/{SystemCon…-11}] skipping snapshot; replica is likely a learner in the process of being added: (n3,s3):2LEARNER
I191022 20:44:07.088068 3087 storage/store_snapshot.go:978  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] sending LEARNER snapshot 716e09cb at applied index 67
I191022 20:44:07.095593 3087 storage/store_snapshot.go:1021  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] streamed snapshot to (n3,s3):2LEARNER: kv pairs: 76, log entries: 0, rate-limit: 8.0 MiB/sec, 0.02s
I191022 20:44:07.102692 32540 storage/replica_raftstorage.go:794  [n3,s3,r6/2:{-}] applying LEARNER snapshot [id=716e09cb index=67]
I191022 20:44:07.123197 32540 storage/replica_raftstorage.go:815  [n3,s3,r6/2:/Table/{SystemCon…-11}] applied LEARNER snapshot [total=20ms ingestion=4@10ms id=716e09cb index=67]
I191022 20:44:07.136278 3087 storage/replica_command.go:1586  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n3,s3):2] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n3,s3):2LEARNER, next=3, gen=1]
I191022 20:44:07.226549 3087 storage/replica_raft.go:291  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA[(n3,s3):2]: after=[(n1,s1):1 (n3,s3):2] next=3
I191022 20:44:07.304734 3087 storage/replica_command.go:1586  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n2,s2):3LEARNER] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n3,s3):2, next=3, gen=2]
I191022 20:44:07.675510 3087 storage/replica_raft.go:291  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA[(n2,s2):3LEARNER]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3LEARNER] next=4
I191022 20:44:07.743099 3087 storage/store_snapshot.go:978  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] sending LEARNER snapshot 022b53af at applied index 72
I191022 20:44:07.745731 3087 storage/store_snapshot.go:1021  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] streamed snapshot to (n2,s2):3LEARNER: kv pairs: 80, log entries: 0, rate-limit: 8.0 MiB/sec, 0.03s
I191022 20:44:07.791135 33135 storage/raft_snapshot_queue.go:125  [n1,raftsnapshot,s1,r6/1:/Table/{SystemCon…-11}] skipping snapshot; replica is likely a learner in the process of being added: (n2,s2):3LEARNER
I191022 20:44:07.807801 33133 storage/replica_raftstorage.go:794  [n2,s2,r6/3:{-}] applying LEARNER snapshot [id=022b53af index=72]
I191022 20:44:07.829345 33133 storage/replica_raftstorage.go:815  [n2,s2,r6/3:/Table/{SystemCon…-11}] applied LEARNER snapshot [total=21ms ingestion=4@18ms id=022b53af index=72]
I191022 20:44:07.853327 3087 storage/replica_command.go:1586  [n1,replicate,s1,r6/1:/Table/{SystemCon…-11}] change replicas (add [(n2,s2):3] remove []): existing descriptor r6:/Table/{SystemConfigSpan/Start-11} [(n1,s1):1, (n3,s3):2, (n2,s2):3LEARNER, next=4, gen=3]
I191022 20:44:07.980950 3087 storage/replica_raft.go:291  [n1,s1,r6/1:/Table/{SystemCon…-11}] proposing ADD_REPLICA[(n2,s2):3]: after=[(n1,s1):1 (n3,s3):2 (n2,s2):3] next=4
I191022 20:44:08.045523 3087 storage/queue.go:1134  [n1,replicate] purgatory is now empty
I191022 20:44:08.101046 2728 testutils/testcluster/testcluster.go:747  WaitForFullReplication took: 21.842206352s
I191022 20:44:08.281428 4416 sql/event_log.go:132  [n1,client=127.0.0.1:44652,user=root] Event: "create_database", target: 52, info: {DatabaseName:data Statement:CREATE DATABASE data User:root}
I191022 20:44:08.493627 7542 storage/queue.go:520  [n3,s3] rate limited in MaybeAdd (merge): throttled on async limiting semaphore
I191022 20:44:08.517869 4416 sql/event_log.go:132  [n1,client=127.0.0.1:44652,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.declined_reservation_timeout Value:00:00:00 User:root}
I191022 20:44:08.688499 4416 sql/event_log.go:132  [n1,client=127.0.0.1:44652,user=root] Event: "set_cluster_setting", target: 0, info: {SettingName:server.failed_reservation_timeout Value:00:00:00 User:root}



TestInitialPartitioning/collatedstring{de}_table
...              [n1,client=127.0.0.1:44652,user=root] query cache hit
              [n1,client=127.0.0.1:44652,user=root] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/92/1
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 KiB
            cockroach.streamid: 1
               === SPAN START: [async] drain ===
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 3.531ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/92/1{-/"\x8bƣ\x89\x91+\x8c\xf5\x1c\x89\xd5b\x00\x00\x00 \x00 \x00 \x00 \x00\x00\x02\x02\x02\x02"}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=92e97552] querying next range at /Table/92/1
              [n2,txn=92e97552] r277: sending batch 1 Scan to (n2,s2):1
              [n2,txn=92e97552] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r277/1:/{Table/92-Max}] read-only path
              [n2,s2,r277/1:/{Table/92-Max}] acquire latches
              [n2,s2,r277/1:/{Table/92-Max}] waited 94.843µs to acquire latches
              [n2,s2,r277/1:/{Table/92-Max}] waiting for read lock
              [n2,s2,r277/1:/{Table/92-Max}] read completed
               === SPAN START: flow ===
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 1.595ms
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:19733] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1296664 [running]:
            runtime/debug.Stack(0xc00283a900, 0x6722640, 0xc0046745a0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc005866600, 0xc00283a900)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc005866600)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc005866600, 0xc003a955c0)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/string_table
...ient=127.0.0.1:44652,user=root] added table 'data.public.string_table' to table collection
              [n1,client=127.0.0.1:44652,user=root] query cache hit
              [n1,client=127.0.0.1:44652,user=root] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/84/1/"y!a,$5\vP%"
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: flow ===
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 7.712ms
              [n1,client=127.0.0.1:44652,user=root] starting scan with limitBatches false
              [n1,client=127.0.0.1:44652,user=root] Scan /Table/84/1/"y!a,$5\vP%"{-/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n1,client=127.0.0.1:44652,user=root,txn=8797b7fe] querying next range at /Table/84/1/"y!a,$5\vP%"
              [n1,client=127.0.0.1:44652,user=root,txn=8797b7fe] r239: sending batch 1 Scan to (n1,s1):1
              [n1,client=127.0.0.1:44652,user=root,txn=8797b7fe] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n1] 1 Scan
              [n1,s1] executing 1 requests
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] read-only path
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] read has no clock uncertainty
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] acquire latches
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] waited 72.796µs to acquire latches
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] waiting for read lock
              [n1,s1,r239/1:/Table/84/1/"y!a,$5\vP%"…] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 457µs
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:15091] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 886763 [running]:
            runtime/debug.Stack(0xc0061b8d50, 0x6722640, 0xc003472f00)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc005c67600, 0xc0061b8d50)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc005c67600)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc005c67600, 0xc0061b9710)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/varbit_table
...2,user=root] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/91/1
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.3 KiB
            cockroach.streamid: 1
               === SPAN START: [async] drain ===
               === SPAN START: flow ===
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 26.023ms
              [n2] starting scan with limitBatches true
              [n2] Scan /Table/91/1{-/B11001100000111000101010000011101000001101010010100100010111110001110111101100100110/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=6367d1df] querying next range at /Table/91/1
              [n2,txn=6367d1df] r273: sending batch 1 Scan to (n2,s2):1
              [n2,txn=6367d1df] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r273/1:/Table/91/1{-/B11001…}] read-only path
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,s2,r273/1:/Table/91/1{-/B11001…}] acquire latches
              [n2,s2,r273/1:/Table/91/1{-/B11001…}] waited 102.326µs to acquire latches
              [n2,s2,r273/1:/Table/91/1{-/B11001…}] waiting for read lock
              [n2,s2,r273/1:/Table/91/1{-/B11001…}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 427µs
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:19200] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1249180 [running]:
            runtime/debug.Stack(0xc003f48db0, 0x6722640, 0xc003e6a6c0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc004945500, 0xc003f48db0)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc004945500)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc004945500, 0xc005fe7770)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b



TestInitialPartitioning/time_table
...   [n1,client=127.0.0.1:44652,user=root] query cache hit
              [n1,client=127.0.0.1:44652,user=root] planning ends
              [n1,client=127.0.0.1:44652,user=root] checking distributability
              [n1,client=127.0.0.1:44652,user=root] will distribute plan: true
              [n1,client=127.0.0.1:44652,user=root] execution starts: distributed engine
               === SPAN START: consuming rows ===
              [n1,client=127.0.0.1:44652,user=root] creating DistSQL plan with isLocal=false
              [n1,client=127.0.0.1:44652,user=root] querying next range at /Table/90/1
              [n1,client=127.0.0.1:44652,user=root] running DistSQL plan
               === SPAN START: /cockroach.sql.distsqlrun.DistSQL/SetupFlow ===
               === SPAN START: outbox ===
            cockroach.stat.outbox.bytes_sent: 2.2 KiB
            cockroach.streamid: 1
               === SPAN START: table reader ===
            cockroach.processorid: 0
            cockroach.stat.tablereader.bytes.read: 0 B
            cockroach.stat.tablereader.input.rows: 0
            cockroach.stat.tablereader.stalltime: 11.826ms
              [n2] starting scan with limitBatches true
               === SPAN START: [async] drain ===
              [n2] Scan /Table/90/1{-/43802567830/#}
               === SPAN START: txn coordinator send ===
               === SPAN START: dist sender send ===
              [n2,txn=bbb374c6] querying next range at /Table/90/1
               === SPAN START: flow ===
              [n1,client=127.0.0.1:44652,user=root] starting (0 processors, 0 startables)
               === SPAN START: noop ===
            cockroach.processorid: 2
              [n2] Consumer sent handshake. Consuming flow scheduled: true
              [n2,txn=bbb374c6] r268: sending batch 1 Scan to (n2,s2):1
              [n2,txn=bbb374c6] sending request to local client
               === SPAN START: /cockroach.roachpb.Internal/Batch ===
              [n2] 1 Scan
              [n2,s2] executing 1 requests
              [n2,s2,r268/1:/{Table/90/1-Max}] read-only path
              [n2,s2,r268/1:/{Table/90/1-Max}] acquire latches
              [n2,s2,r268/1:/{Table/90/1-Max}] waited 56.977µs to acquire latches
              [n2,s2,r268/1:/{Table/90/1-Max}] waiting for read lock
              [n2,s2,r268/1:/{Table/90/1-Max}] read completed
               === SPAN START: count rows ===
            cockroach.processorid: 1
            cockroach.stat.aggregator.input.rows: 0
            cockroach.stat.aggregator.mem.max: 0 B
            cockroach.stat.aggregator.stalltime: 1.679ms
              [n1,client=127.0.0.1:44652,user=root] execution ends
              [n1,client=127.0.0.1:44652,user=root] rows affected: 1
              [n1,client=127.0.0.1:44652,user=root] AutoCommit. err: <nil>
              [n1,client=127.0.0.1:44652,user=root] releasing 1 tables
               === SPAN START: exec stmt ===
              [n1,client=127.0.0.1:44652,user=root] [NoTxn pos:18715] executing ExecStmt: SET TRACING = off
              [n1,client=127.0.0.1:44652,user=root] executing: SET TRACING = off in state: NoTxn
            goroutine 1196197 [running]:
            runtime/debug.Stack(0xc005b80210, 0x6722640, 0xc0050ed1c0)
            	/usr/local/go/src/runtime/debug/stack.go:24 +0xab
            github.com/cockroachdb/cockroach/pkg/testutils.SucceedsSoon(0x6816940, 0xc00140dc00, 0xc005b80210)
            	/go/src/github.com/cockroachdb/cockroach/pkg/testutils/soon.go:37 +0x87
            github.com/cockroachdb/cockroach/pkg/ccl/partitionccl.TestInitialPartitioning.func1(0xc00140dc00)
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/partitionccl/partition_test.go:1196 +0x23a
            testing.tRunner(0xc00140dc00, 0xc006651710)
            	/usr/local/go/src/testing/testing.go:865 +0x164
            created by testing.(*T).Run
            	/usr/local/go/src/testing/testing.go:916 +0x65b

Please assign, take a look and update the issue accordingly.
@cockroach-teamcity cockroach-teamcity added C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot. labels Oct 22, 2019
@cockroach-teamcity cockroach-teamcity added this to the 19.2 milestone Oct 22, 2019
andreimatei added a commit to andreimatei/cockroach that referenced this issue Oct 23, 2019
@andreimatei
all: Revert cockroachdb#39722
0cf7360 
This reverts commit 0b0c71f, reversing
changes made to 9b36103.

Reverting "config,sqlbase: move computation of splits for SQL tables to
sqlbase". It seems to have caused TestInitialPartitioning and
TestRepartitioning to timeout often when run under testrace on TC (only
when the build runs on the master branch and these tests are run in
conjunction with all the other packages). I don't know what's wrong yet.

Fixes cockroachdb#41812
Fixes cockroachdb#41821
Fixes cockroachdb#41825
Fixes cockroachdb#41831
Fixes cockroachdb#41835
Fixes cockroachdb#41843
Fixes cockroachdb#41846
Fixes cockroachdb#41850
Fixes cockroachdb#41862
Fixes cockroachdb#41874
Fixes cockroachdb#41879

Fixes cockroachdb#41652
Fixes cockroachdb#41813
Fixes cockroachdb#41822
Fixes cockroachdb#41826
Fixes cockroachdb#41832
Fixes cockroachdb#41836
Fixes cockroachdb#41844
Fixes cockroachdb#41847
Fixes cockroachdb#41851
Fixes cockroachdb#41868
Fixes cockroachdb#41875

Release note: None
@andreimatei andreimatei mentioned this issue Oct 23, 2019
Merged
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees
No one assigned
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Milestone
19.2
Development

Successfully merging a pull request may close this issue.

all: Revert #39722 andreimatei/cockroach
1 participant
@cockroach-teamcity