roachtest: tpccbench/nodes=9/cpu=4/multi-region failed

[cockroach-teamcity]

(roachtest).tpccbench/nodes=9/cpu=4/multi-region failed on provisional_202008241848_v20.1.5@f990441079c686f9eec32d80044c719175a2bee5:

The test failed on branch=provisional_202008241848_v20.1.5, cloud=gce:
test artifacts and logs in: /home/agent/work/.go/src/github.com/cockroachdb/cockroach/artifacts/tpccbench/nodes=9/cpu=4/multi-region/run_1
	cluster.go:2597,tpcc.go:782,tpcc.go:617,test_runner.go:754: monitor failure: monitor task failed: failed with output "I200825 22:09:10.901685 1 workload/cli/run.go:356  creating load generator...\nInitializing 5000 connections...\nInitializing 5000 workers and preparing statements...\nE200825 22:27:07.259214 1 workload/cli/run.go:379  Attempt to create load generator failed. It's been more than 10m0s since we started trying to create the load generator so we're giving up. Last failure: failed to initialize the load generator: preparing \n\t\tUPDATE district\n\t\tSET d_next_o_id = d_next_o_id + 1\n\t\tWHERE d_w_id = $1 AND d_id = $2\n\t\tRETURNING d_tax, d_next_o_id: context deadline exceeded\nError: failed to initialize the load generator: preparing \n\t\tUPDATE district\n\t\tSET d_next_o_id = d_next_o_id + 1\n\t\tWHERE d_w_id = $1 AND d_id = $2\n\t\tRETURNING d_tax, d_next_o_id: context deadline exceeded\nError: COMMAND_PROBLEM: exit status 1\n(1) COMMAND_PROBLEM\nWraps: (2) Node 4. Command with error:\n  | ```\n  | ./workload run tpcc --warehouses=5000 --workers=5000 --max-rate=2500 --wait=false --duration=1h40m0s --scatter --tolerate-errors  {pgurl:1-3,5-7,9-11}\n  | ```\nWraps: (3) exit status 1\nError types: (1) errors.Cmd (2) *hintdetail.withDetail (3) *exec.ExitError\n": /home/agent/work/.go/src/github.com/cockroachdb/cockroach/bin/roachprod run teamcity-2221186-1598354118-70-n12cpu4-geo:4 -- ./workload run tpcc --warehouses=5000 --workers=5000 --max-rate=2500 --wait=false --duration=1h40m0s --scatter --tolerate-errors  {pgurl:1-3,5-7,9-11}: exit status 20
		(1) attached stack trace
		  -- stack trace:
		  | main.(*monitor).WaitE
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2585
		  | main.(*monitor).Wait
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2593
		  | main.runTPCCBench
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:782
		  | main.registerTPCCBenchSpec.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:617
		  | main.(*testRunner).runTest.func2
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/test_runner.go:754
		Wraps: (2) monitor failure
		Wraps: (3) attached stack trace
		  -- stack trace:
		  | main.(*monitor).wait.func2
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2641
		Wraps: (4) monitor task failed
		Wraps: (5) attached stack trace
		  -- stack trace:
		  | main.loadTPCCBench
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:710
		  | [...repeated from below...]
		Wraps: (6) failed with output "I200825 22:09:10.901685 1 workload/cli/run.go:356  creating load generator...\nInitializing 5000 connections...\nInitializing 5000 workers and preparing statements...\nE200825 22:27:07.259214 1 workload/cli/run.go:379  Attempt to create load generator failed. It's been more than 10m0s since we started trying to create the load generator so we're giving up. Last failure: failed to initialize the load generator: preparing \n\t\tUPDATE district\n\t\tSET d_next_o_id = d_next_o_id + 1\n\t\tWHERE d_w_id = $1 AND d_id = $2\n\t\tRETURNING d_tax, d_next_o_id: context deadline exceeded\nError: failed to initialize the load generator: preparing \n\t\tUPDATE district\n\t\tSET d_next_o_id = d_next_o_id + 1\n\t\tWHERE d_w_id = $1 AND d_id = $2\n\t\tRETURNING d_tax, d_next_o_id: context deadline exceeded\nError: COMMAND_PROBLEM: exit status 1\n(1) COMMAND_PROBLEM\nWraps: (2) Node 4. Command with error:\n  | ```\n  | ./workload run tpcc --warehouses=5000 --workers=5000 --max-rate=2500 --wait=false --duration=1h40m0s --scatter --tolerate-errors  {pgurl:1-3,5-7,9-11}\n  | ```\nWraps: (3) exit status 1\nError types: (1) errors.Cmd (2) *hintdetail.withDetail (3) *exec.ExitError\n"
		Wraps: (7) attached stack trace
		  -- stack trace:
		  | main.execCmdWithBuffer
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:552
		  | main.(*cluster).RunWithBuffer
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2266
		  | main.loadTPCCBench
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:709
		  | main.runTPCCBench.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/tpcc.go:780
		  | main.(*monitor).Go.func1
		  | 	/home/agent/work/.go/src/github.com/cockroachdb/cockroach/pkg/cmd/roachtest/cluster.go:2575
		  | golang.org/x/sync/errgroup.(*Group).Go.func1
		  | 	/home/agent/work/.go/pkg/mod/golang.org/x/sync@v0.0.0-20190911185100-cd5d95a43a6e/errgroup/errgroup.go:57
		  | runtime.goexit
		  | 	/usr/local/go/src/runtime/asm_amd64.s:1357
		Wraps: (8) /home/agent/work/.go/src/github.com/cockroachdb/cockroach/bin/roachprod run teamcity-2221186-1598354118-70-n12cpu4-geo:4 -- ./workload run tpcc --warehouses=5000 --workers=5000 --max-rate=2500 --wait=false --duration=1h40m0s --scatter --tolerate-errors  {pgurl:1-3,5-7,9-11}
		Wraps: (9) exit status 20
		Error types: (1) *withstack.withStack (2) *errutil.withPrefix (3) *withstack.withStack (4) *errutil.withPrefix (5) *withstack.withStack (6) *errutil.withPrefix (7) *withstack.withStack (8) *errutil.withPrefix (9) *exec.ExitError

More

Artifacts: /tpccbench/nodes=9/cpu=4/multi-region
Related:

• roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #53414 roachtest: tpccbench/nodes=9/cpu=4/multi-region failed C-test-failure O-roachtest O-robot branch-release-19.1 release-blocker

• roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #52337 roachtest: tpccbench/nodes=9/cpu=4/multi-region failed C-test-failure O-roachtest O-robot branch-provisional_202008031850_v20.2.0-alpha.3 release-blocker

• roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #52206 roachtest: tpccbench/nodes=9/cpu=4/multi-region failed C-test-failure O-roachtest O-robot branch-release-20.1 release-blocker

• roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #50698 roachtest: tpccbench/nodes=9/cpu=4/multi-region failed C-test-failure O-roachtest O-robot branch-release-19.2 release-blocker

• roachtest: tpccbench/nodes=9/cpu=4/multi-region failed #48255 roachtest: tpccbench/nodes=9/cpu=4/multi-region failed C-test-failure O-roachtest O-robot branch-master release-blocker

See this test on roachdash
_{powered by pkg/cmd/internal/issues}

[knz]

a SQL query is failing with context deadline exceeded

this looks like a plain timeout

[tbg]

Reassigning to Nathan since he runs all of the tpccbench tests right now anyway

[nvanbenschoten]

I have a new theory about this after hitting it a few times while debugging other issues. I think this is because we perform the "warmup" phase by running unpartitioned load from a single load gen against all CRDB nodes. This means that we're preparing statements over a WAN, which is never the case during normal multi-region TPC-C operation. We should stop doing this, either by running partitioned load or by only pointing the load gen at local CRDB nodes.

[tbg]

@nvanbenschoten is this scheduled for any time soon? If not, we should.

[nvanbenschoten]

I've bumped this timeout to 60m in #55300. I think the entire timeout was misguided and probably shouldn't have been introduced in the first place, but 60m at least accounts for the fact that statements can take a while to prepare for large datasets. I'm checking to see whether that improves the situation.

[tbg]

Still failing with a 60m timeout in #55939