SELECT query not responding

Hi there,

I’m working on a simple comparison of RDMS for simple CRUD things.


I already have 2 schemas under testing now and the results (temporary) can be seen here:
http://playwithsql-summary.surge.sh/

I have though a huge problem with cockroachdb (currently using v1.0.1 but it happened to all versions before). It gets stuck on updates forever.
Once it is stuck, I can’t even do a select on the table, it will never reply.
the CPU and RAM are fine.

to reproduce:
get docker with experimental flag on.
git clone https://github.com/vincentserpoul/playwithsql into go/src/github.com/vincentserpoul/playwithsql
./infra/databases/swarm/cockroachdb/launch-solo.sh
And then, according to the schema you want to try (all are stuck):
go run ./bench/status/main.go --db=cockroachdb --sch=lateststatus --loops=10 --maxconns=10 --concurrency=10
go run ./bench/status/main.go --db=cockroachdb --sch=islatest --loops=10 --maxconns=10 --concurrency=10
go run ./bench/status/main.go --db=cockroachdb --sch=history --loops=10 --maxconns=10 --concurrency=10

Here are the latest logs

I170529 05:25:24.258725 144 gossip/gossip.go:448  [n1] gossip status (ok, 1 node)
gossip client (0/3 cur/max conns)
gossip server (0/3 cur/max conns, infos 0/0 sent/received, bytes 0B/0B sent/received)
I170529 05:25:24.259034 145 server/status/runtime.go:225  [n1] runtime stats: 72 MiB RSS, 161 goroutines, 18 MiB/4.1 MiB/32 MiB GO alloc/idle/total, 9.0 MiB/16 MiB CGO alloc/total, 203.43cgo/sec, 0.02/0.02 %(u/s)time, 0.00 %gc (1x)
I170529 05:25:34.259724 145 server/status/runtime.go:225  [n1] runtime stats: 73 MiB RSS, 160 goroutines, 16 MiB/6.7 MiB/33 MiB GO alloc/idle/total, 9.8 MiB/17 MiB CGO alloc/total, 207.69cgo/sec, 0.02/0.02 %(u/s)time, 0.00 %gc (1x)
I170529 05:25:52.058447 104 storage/replica_proposal.go:390  [n1,s1,r16/1:/{Table/55-Max}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=1 pro=1496035342.848359948,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0
I170529 05:25:52.058606 4454 sql/event_log.go:101  [client=10.255.0.3:53476,user=root,n1] Event: "create_table", target: 57, info: {TableName:entityone Statement:CREATE TABLE IF NOT EXISTS entityone (entityone_id BIGSERIAL NOT NULL, time_created DATE NOT NULL DEFAULT '2017-05-29', entityone_status_id BIGINT NOT NULL, PRIMARY KEY (entityone_id), CONSTRAINT e_fk_esi FOREIGN KEY (entityone_status_id) REFERENCES entityone_status (entityone_status_id)) User:root}
I170529 05:25:52.060233 146 storage/split_queue.go:92  [split,n1,s1,r17/1:/{Table/56-Max}] splitting at key /Table/57/0
I170529 05:25:52.060260 146 storage/replica_command.go:2632  [split,n1,s1,r17/1:/{Table/56-Max}] initiating a split of this range at key /Table/57 [r18]
I170529 05:25:52.070277 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=56 (entityone_status) version=2 mtime=2017-05-29 05:25:52.070254312 +0000 UTC
I170529 05:25:52.079443 125 storage/replica_proposal.go:390  [n1,s1,r17/1:/{Table/56-Max}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=1 pro=1496035342.848359948,0 following repl=(n0,s0):? start=0.000000000,0 exp=0.000000000,0
I170529 05:25:52.086563 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=57 (entityone) version=2 mtime=2017-05-29 05:25:52.086536981 +0000 UTC
I170529 05:25:52.090314 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=57 (entityone) version=3 mtime=2017-05-29 05:25:52.090297594 +0000 UTC
I170529 05:25:52.099586 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: CREATE INDEX es_idx_esi ON entityone(entityone_status_id)
I170529 05:25:52.107861 4454 sql/event_log.go:101  [client=10.255.0.3:53476,user=root,n1] Event: "create_index", target: 57, info: {TableName:entityone IndexName:es_idx_esi Statement:CREATE INDEX es_idx_esi ON entityone (entityone_status_id) User:root MutationID:1}
I170529 05:25:52.115121 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=57 (entityone) version=4 mtime=2017-05-29 05:25:52.1150968 +0000 UTC
I170529 05:25:52.118672 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=57 (entityone) version=5 mtime=2017-05-29 05:25:52.118651359 +0000 UTC
I170529 05:25:52.121629 4454 sql/backfill.go:132  [client=10.255.0.3:53476,user=root,n1] Running backfill for "entityone", v=5, m=1
I170529 05:25:52.131528 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=57 (entityone) version=6 mtime=2017-05-29 05:25:52.131505919 +0000 UTC
I170529 05:25:52.137382 4454 sql/event_log.go:101  [client=10.255.0.3:53476,user=root,n1] Event: "finish_schema_change", target: 57, info: {MutationID:1}
I170529 05:25:52.139337 4454 sql/lease.go:301  publish (count leases): descID=57 name=entityone version=5 count=1
I170529 05:25:52.165988 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: CREATE INDEX es_idx_si ON entityone_status(status_id)
I170529 05:25:52.173004 4454 sql/event_log.go:101  [client=10.255.0.3:53476,user=root,n1] Event: "create_index", target: 56, info: {TableName:entityone_status IndexName:es_idx_si Statement:CREATE INDEX es_idx_si ON entityone_status (status_id) User:root MutationID:1}
I170529 05:25:52.178703 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=56 (entityone_status) version=3 mtime=2017-05-29 05:25:52.178680724 +0000 UTC
I170529 05:25:52.182094 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=56 (entityone_status) version=4 mtime=2017-05-29 05:25:52.182075873 +0000 UTC
I170529 05:25:52.185430 4454 sql/backfill.go:132  [client=10.255.0.3:53476,user=root,n1] Running backfill for "entityone_status", v=4, m=1
I170529 05:25:52.199704 4454 sql/lease.go:372  [client=10.255.0.3:53476,user=root,n1] publish: descID=56 (entityone_status) version=5 mtime=2017-05-29 05:25:52.199679366 +0000 UTC
I170529 05:25:52.204761 4454 sql/event_log.go:101  [client=10.255.0.3:53476,user=root,n1] Event: "finish_schema_change", target: 56, info: {MutationID:1}
I170529 05:25:52.207007 4454 sql/lease.go:301  publish (count leases): descID=56 name=entityone_status version=4 count=1
I170529 05:25:52.245558 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: BEGIN
I170529 05:25:52.248659 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: BEGIN
I170529 05:25:52.248673 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249054 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249109 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249400 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249436 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249740 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: BEGIN
I170529 05:25:52.249765 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest: BEGIN
I170529 05:25:52.250105 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.250526 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest: BEGIN
I170529 05:25:52.251455 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.251882 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.252100 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.252344 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.252410 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.252632 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.252672 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.253301 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.254094 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.255314 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.257926 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: COMMIT
I170529 05:25:52.259721 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.260243 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.260705 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.260904 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.261137 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.261219 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.261464 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.261680 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.264689 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest: COMMIT
I170529 05:25:52.267688 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: COMMIT
I170529 05:25:52.267956 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest:
		INSERT INTO entityone (entityone_id, time_created, entityone_status_id)
		VALUES(DEFAULT, DEFAULT, $1)
		RETURNING entityone_id

I170529 05:25:52.268505 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: COMMIT
I170529 05:25:52.268632 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest: COMMIT
I170529 05:25:52.269319 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: COMMIT
I170529 05:25:52.270723 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest: COMMIT
I170529 05:25:52.270881 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: COMMIT
I170529 05:25:52.271030 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: COMMIT
I170529 05:25:52.276302 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: COMMIT
I170529 05:25:52.281064 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: BEGIN
I170529 05:25:52.281235 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: BEGIN
I170529 05:25:52.281371 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest: BEGIN
I170529 05:25:52.281836 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: BEGIN
I170529 05:25:52.281871 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: BEGIN
I170529 05:25:52.281968 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: BEGIN
I170529 05:25:52.282017 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest: BEGIN
I170529 05:25:52.282149 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: BEGIN
I170529 05:25:52.282297 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest: BEGIN
I170529 05:25:52.282469 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: BEGIN
I170529 05:25:52.282922 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.283370 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.283556 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.283887 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.284213 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.284468 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.285126 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.285616 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.286061 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.286494 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.290853 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.292565 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.292899 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.295035 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: COMMIT
I170529 05:25:52.296826 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.302160 5121 sql/executor.go:582  [client=10.255.0.3:53490,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.311122 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.312749 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.313390 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: COMMIT
I170529 05:25:52.314275 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.314984 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.315394 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.322623 5062 sql/executor.go:728  [client=10.255.0.3:53480,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=b779b402 key=/Table/56/1/248922611001458689/0 rw=true pri=0.01286049 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.283937519,1 orig=1496035552.282971073,0 max=1496035552.282971073,0 wto=false rop=false seq=2
I170529 05:25:52.324592 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: BEGIN
I170529 05:25:52.325514 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.328940 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.337759 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: COMMIT
I170529 05:25:52.348762 4454 sql/executor.go:728  [client=10.255.0.3:53476,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=15073786 key=/Table/56/1/248922611003031553/0 rw=true pri=0.05142880 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.283937519,1 orig=1496035552.283439913,0 max=1496035552.283439913,0 wto=false rop=false seq=2
I170529 05:25:52.352393 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: BEGIN
I170529 05:25:52.354147 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.358292 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.366446 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: COMMIT
I170529 05:25:52.382746 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: COMMIT
I170529 05:25:52.385326 5100 sql/executor.go:728  [client=10.255.0.3:53482,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=93a3a201 key=/Table/56/1/248922611010174977/0 rw=true pri=0.00093519 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.286097841,1 orig=1496035552.285659465,0 max=1496035552.285659465,0 wto=false rop=false seq=2
I170529 05:25:52.388201 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: BEGIN
I170529 05:25:52.389132 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.392086 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.400034 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: COMMIT
I170529 05:25:52.416811 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: COMMIT
I170529 05:25:52.419921 5063 sql/executor.go:728  [client=10.255.0.3:53492,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=dfd88477 key=/Table/56/1/248922611008831489/0 rw=true pri=0.08092648 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.286537017,1 orig=1496035552.285226381,0 max=1496035552.285226381,0 wto=false rop=false seq=2
I170529 05:25:52.423224 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: BEGIN
I170529 05:25:52.424692 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.428031 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.433327 5101 sql/executor.go:582  [client=10.255.0.3:53494,user=root,n1] execRequest: COMMIT
I170529 05:25:52.436402 5101 sql/executor.go:728  [client=10.255.0.3:53494,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=3dff2a59 key=/Table/56/1/248922611005292545/0 rw=true pri=0.06814338 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.286537017,1 orig=1496035552.284245252,0 max=1496035552.284245252,0 wto=false rop=false seq=2
I170529 05:25:52.441091 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: BEGIN
I170529 05:25:52.442211 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.445029 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.449806 5118 sql/executor.go:582  [client=10.255.0.3:53486,user=root,n1] execRequest: COMMIT
I170529 05:25:52.465798 5120 sql/executor.go:582  [client=10.255.0.3:53484,user=root,n1] execRequest: COMMIT
I170529 05:25:52.469905 5120 sql/executor.go:728  [client=10.255.0.3:53484,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=edd495b3 key=/Table/56/1/248922611013976065/0 rw=true pri=0.02509370 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.325567741,1 orig=1496035552.283604916,0 max=1496035552.283604916,0 wto=false rop=false seq=2
I170529 05:25:52.474291 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: BEGIN
I170529 05:25:52.475377 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.478650 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2
I170529 05:25:52.480526 5062 sql/executor.go:582  [client=10.255.0.3:53480,user=root,n1] execRequest: COMMIT
I170529 05:25:52.491326 5097 sql/executor.go:582  [client=10.255.0.3:53488,user=root,n1] execRequest: COMMIT
I170529 05:25:52.503168 5100 sql/executor.go:582  [client=10.255.0.3:53482,user=root,n1] execRequest: COMMIT
I170529 05:25:52.517673 4454 sql/executor.go:582  [client=10.255.0.3:53476,user=root,n1] execRequest: COMMIT
I170529 05:25:52.520844 4454 sql/executor.go:728  [client=10.255.0.3:53476,user=root,n1] execRequest: error: HandledRetryableTxnError: TransactionRetryError: retry txn "sql txn" id=c27aee52 key=/Table/56/1/248922611349225473/0 rw=true pri=0.00140029 iso=SERIALIZABLE stat=PENDING epo=0 ts=1496035552.442252299,1 orig=1496035552.389171941,0 max=1496035552.389171941,0 wto=false rop=false seq=2
I170529 05:25:52.523820 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: BEGIN
I170529 05:25:52.524981 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest:
		INSERT INTO entityone_status(entityone_status_id, time_created, action_id, status_id)
		VALUES(DEFAULT, DEFAULT, $1, $2)
		RETURNING entityone_status_id

I170529 05:25:52.528216 5096 sql/executor.go:582  [client=10.255.0.3:53478,user=root,n1] execRequest: COMMIT
I170529 05:25:52.530511 5063 sql/executor.go:582  [client=10.255.0.3:53492,user=root,n1] execRequest: UPDATE entityone SET entityone_status_id = $1 WHERE entityone_id = $2

Tagging in @arjun to help out here.

1 Like

Hi Vincent,

Thank you for the detailed instructions. I have reproduced the problem.

I go run ..., and within a couple minutes, the cockroach cluster no longer responds to SELECT queries on the playwithsql database.

I’ve forked your repo here as I needed to strip out Oracle dependencies to get it to compile without manually fetching some dependencies. This Oracle-free fork is easier to build, as it builds out of the box with go build.

I’m off for the rest of the week, so tagging in @cdo and @marc to help track down this bug. Thank you again or the report!

I’m working quite a lot on it until tomorrow, so maybe it’s better I create a specific branch with no oracle directly on my repo. Will keep the post updated!

By the way, the schemas I’m testing don’t always make sense, but it just to see how they performs compare to eachother and cockroach is lagging behind for now.

I have added one more use case, cockroach still lags behind :/.

I will update the results soon and publish them to HN.
It would be nice if we can solve the issue before.

Hi Vincent

thanks for the update. Thank you so much for your attention and we’ll keep a close look at your experiments. :slight_smile:
it’s a bit rushed on our side though, sorry for the slow turnaround. We’re not ignoring your issues, but it takes us a little more time to investigate the problems than for you to find them. I hope you understand that.

Meanwhile, we’ll love to study your experimental protocol to understand what you’re measuring and how you’re comparing stuff.

Out of curiosity, as I am looking at http://playwithsql-summary.surge.sh/ – have you configured the other database engines for 3-way replication? It would seem a bit unfair to compare otherwise.

It would also be nice to see the SQL queries being executed in the web interface!

For now, I am running all instances as single entities (cockroachdb included).
I am running 50 go routines concurrently within each runs sequentially:

  • 10000 inserts
    then
  • 10000 updates
    then
  • 10000 select with a pk filter (1 row returned)
    then
  • 10000 select with a status filter (status_id column)

for each of the goroutine, I run the queries sequencially with a pause time between each if things tend to slow down and decreasing otherwise (but all is between 1ms to 200ms pausetime)

I’m trying to simply measure how long it takes on a n1-standard-1 machine on gcloud kubernetes GKE or local swarm cluster.

I understand totally you are under pressure, especially after the v1 has been announced.
I’m really happy that cockroach is around and I’d be really glad to help as I really wanna use it for my go-to RDMS (which is why I am testing).

Displaying the select queries in the web int is a very good idea, I ll do it asap!

Out of curiosity, do you place a barrier between the insert and update workloads, or between the update and select workloads? Or is it possible that some goroutines can start issueing the selects while others are still busy with updates?

I would recommend that you separately benchmark homogeneous and heterogeneous workloads, as I’d expect they have quite different performance profiles.

The result are not final here as I ran them with a lot less loops, so don’t bother too much on looking at them.
What matters more would be to actually be able to end the tests in cockroachdb with the numbers defined above

They are all separated.
That was my thoughts at the beginning, but I checked and surely wait until all go routines to finish (waitgroup) before I start the next round

Thanks for clarifying. So to draw the full picture of your initial report again, do you confirm that the insert and update parts of the workload did complete (albeit slowly), and only failed (or hanging) on the first select part?

The few times I checked where it was stuck was indeed at the select step.
I ll try to rerun it to make sure

I’ve added a new schema for testing, which is more straightforward, and this time hanging on UPDATE (2 queries, see below)

DDL

    CREATE TABLE IF NOT EXISTS entityone (
        entityone_id BIGSERIAL NOT NULL,
        status_id INT NOT NULL DEFAULT 1,
        action_id INT NOT NULL DEFAULT 1,
        time_created DATE NOT NULL DEFAULT CURRENT_DATE,
        time_updated DATE NOT NULL DEFAULT CURRENT_DATE,
        PRIMARY KEY (entityone_id)
    );

    CREATE TABLE IF NOT EXISTS entityone_history (
        entityone_id BIGINT NOT NULL,
        action_id INT NOT NULL DEFAULT 1,
        status_id INT NOT NULL DEFAULT 1,
        time_created DATE NOT NULL DEFAULT CURRENT_DATE,
        CONSTRAINT es_fk_e_eid
            FOREIGN KEY (entityone_id)
            REFERENCES entityone (entityone_id)
    );

CREATE INDEX es_idx_eid ON entityone_history(entityone_id);
CREATE INDEX e_idx_sid ON entityone(status_id);
CREATE INDEX es_idx_sid ON entityone_history(status_id);

hanging UPDATE (2 queries for each UPDATE):

UPDATE entityone
SET action_id = :actionID, status_id = :statusID, time_updated=:timeUpdated
WHERE entityone_id = :entityoneID

INSERT INTO entityone_history(entityone_id, action_id, status_id)
VALUES (:entityoneID, :actionID, :statusID)

Note that it works if all updates are sequential (go test bench works perfectly well)
It starts to hang on my machine with 4 concurrent goroutines.

All of these go through quickly - increasing concurrence from 1 to 3:

go run ./bench/status/main.go --db=cockroachdb --sch=history --loops=100 --maxconns=10 --concurrency=1
go run ./bench/status/main.go --db=cockroachdb --sch=history --loops=100 --maxconns=10 --concurrency=2
go run ./bench/status/main.go --db=cockroachdb --sch=history --loops=100 --maxconns=10 --concurrency=3

When concurrence is above 4 or more, it hangs:

go run ./bench/status/main.go --db=cockroachdb --sch=history --loops=100 --maxconns=10 --concurrency=5

Briefly testing locally and it looks like the select calls are taking longer than 100ms and BenchmarkSelectEntityoneByStatus has a 100ms timeout. Still poking around as I don’t really understand what is going on.

Replacing the 100ms timeout context with context.Background() in both BenchmarkSelectEntityoneByStatus and BenchmarkSelectEntityoneOneByPK allows the test to complete.

@vincentserpoul I suspect there is something fouled up with the handling of timeouts. Not sure if it is in your code or in ours, but my initial suspicion is yours as I’m not seeing anything errant in the CockroachDB logs.

@radu Can you take a look at the performance of the SELECT queries in the benchmarks mentioned above?

1 Like

I just removed all the timeouts and things go through. That will allow me to finally get some results :slight_smile:.

That said, once the timeout is reached, shouldn’t the query be cancelled and immediately return an error? Or Have I just misunderstood the go context?

That said, once the timeout is reached, shouldn’t the query be cancelled and immediately return an error? Or Have I just misunderstood the go context?

Yes, it should. On the surface, I don’t see a problem with your code. What you’re doing should be fine, but clearly the timeout is fouling something up.

PS Adding some timing instrumentation shows that the SelectEntityoneOneByStatus queries are taking ~300ms and the SelectEntityoneOneByPK queries are taking ~200ms. These queries seem to be dependent on the prior create and update loops as these queries complete in <10ms when using --loops=10. The slower execution is with --loops=1000.