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.

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

ccl/workloadccl/allccl: TestAllRegisteredImportFixture failed #47015

Closed
cockroach-teamcity opened this issue Apr 3, 2020 · 21 comments
Closed
Assignees
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Milestone

Comments

@cockroach-teamcity
Copy link
Member

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@441fef63b21f6b759af5bb28186ea6aba72ebf51:

I200403 21:22:39.473692 17596 jobs/registry.go:797  [n1] job 543550856656027649: stepping through state succeeded with error <nil>
I200403 21:22:39.754123 17763 jobs/registry.go:797  [n1] job 543550856773402625: stepping through state succeeded with error <nil>
I200403 21:22:39.809395 18592 kv/kvserver/replica_command.go:397  [n1,split,s1,r68/1:/Table/6{0/2-1/1}] initiating a split of this range at key /Table/61 [r71] (zone config)
I200403 21:22:39.820028 17596 jobs/registry.go:952  [n1] job 543550856656027649: status succeeded after adoption finished
I200403 21:22:39.895985 16497 ccl/workloadccl/fixture.go:446  imported 114 KiB in new_order table (9000 rows, 0 index entries, took 2.590949808s, 0.04 MiB/s)
I200403 21:22:39.964604 17763 jobs/registry.go:952  [n1] job 543550856773402625: status succeeded after adoption finished
I200403 21:22:40.002717 16493 ccl/workloadccl/fixture.go:446  imported 1017 B in district table (10 rows, 0 index entries, took 2.69743931s, 0.00 MiB/s)
I200403 21:22:40.748485 17575 jobs/registry.go:797  [n1] job 543550856649474049: stepping through state succeeded with error <nil>
I200403 21:22:40.819921 17567 jobs/registry.go:797  [n1] job 543550856673361921: stepping through state succeeded with error <nil>
I200403 21:22:40.847079 17575 jobs/registry.go:952  [n1] job 543550856649474049: status succeeded after adoption finished
I200403 21:22:40.935310 17567 jobs/registry.go:952  [n1] job 543550856673361921: status succeeded after adoption finished
I200403 21:22:40.979641 16496 ccl/workloadccl/fixture.go:446  imported 1.5 MiB in order table (30000 rows, 30000 index entries, took 3.674831874s, 0.41 MiB/s)
I200403 21:22:40.987514 18246 kv/kvserver/replica_command.go:397  [n1,s1,r67/1:/Table/60/{1-2}] initiating a split of this range at key /Table/60/1/0/1/1 [r72] (manual)
I200403 21:22:41.444470 17651 jobs/registry.go:797  [n1] job 543550856698134529: stepping through state succeeded with error <nil>
I200403 21:22:41.450851 17630 jobs/registry.go:797  [n1] job 543550856687386625: stepping through state succeeded with error <nil>
I200403 21:22:41.603209 17651 jobs/registry.go:952  [n1] job 543550856698134529: status succeeded after adoption finished
I200403 21:22:41.605015 16494 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 4.299634243s, 4.08 MiB/s)
I200403 21:22:41.609201 17630 jobs/registry.go:952  [n1] job 543550856687386625: status succeeded after adoption finished
I200403 21:22:41.610385 16495 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 4.305619577s, 1.00 MiB/s)
I200403 21:22:41.913664 18375 kv/kvserver/replica_command.go:397  [n1,s1,r66/1:/Table/59/{1-2}] initiating a split of this range at key /Table/59/1/0/1 [r73] (manual)
I200403 21:22:42.474836 17637 jobs/registry.go:797  [n1] job 543550856718385153: stepping through state succeeded with error <nil>
I200403 21:22:42.488074 17637 jobs/registry.go:952  [n1] job 543550856718385153: status succeeded after adoption finished
I200403 21:22:42.488303 17507 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 5.182914498s, 6.13 MiB/s)
I200403 21:22:42.905807 18087 kv/kvserver/replica_command.go:397  [n1,s1,r54/1:/Table/53/{1-2}] initiating a split of this range at key /Table/53/1/0/1/-3001/1 [r74] (manual)
I200403 21:22:43.892076 17543 jobs/registry.go:797  [n1] job 543550856604450817: stepping through state succeeded with error <nil>
I200403 21:22:43.903362 17543 jobs/registry.go:952  [n1] job 543550856604450817: status succeeded after adoption finished
I200403 21:22:43.903610 17508 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 6.598893785s, 3.29 MiB/s)
I200403 21:22:43.903910 16594 util/stop/stopper.go:539  quiescing
    --- FAIL: TestAllRegisteredImportFixture/tpcc (6.87s)
        all_test.go:95: sql: no rows in result set
            importing table item
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@575a5bd7a8714464a74f52f337dc5af33558ebb0:

I200415 14:19:08.546592 17446 jobs/registry.go:803  [n1] job 546864980326514689: stepping through state succeeded with error <nil>
I200415 14:19:08.780162 17446 jobs/registry.go:958  [n1] job 546864980326514689: status succeeded after adoption finished
I200415 14:19:08.808962 17298 ccl/workloadccl/fixture.go:446  imported 1017 B in district table (10 rows, 0 index entries, took 1.292887779s, 0.00 MiB/s)
I200415 14:19:09.386545 17426 jobs/registry.go:803  [n1] job 546864980069089281: stepping through state succeeded with error <nil>
I200415 14:19:09.628547 17426 jobs/registry.go:958  [n1] job 546864980069089281: status succeeded after adoption finished
I200415 14:19:09.707386 17301 ccl/workloadccl/fixture.go:446  imported 1.5 MiB in order table (30000 rows, 30000 index entries, took 2.190464907s, 0.69 MiB/s)
I200415 14:19:09.763939 16422 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200415 14:19:09.764152 16422 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200415 14:19:09.880995 17610 kv/kvserver/replica_command.go:397  [n1,s1,r34/1:/Table/54/{1-2}] initiating a split of this range at key /Table/54/1/0/1/1 [r82] (manual)
I200415 14:19:10.595582 17217 jobs/registry.go:803  [n1] job 546864980060962817: stepping through state succeeded with error <nil>
I200415 14:19:10.681141 17217 jobs/registry.go:958  [n1] job 546864980060962817: status succeeded after adoption finished
I200415 14:19:10.693037 17299 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 3.177228419s, 5.53 MiB/s)
I200415 14:19:10.770804 17056 jobs/registry.go:803  [n1] job 546864980124860417: stepping through state succeeded with error <nil>
I200415 14:19:10.825898 17056 jobs/registry.go:958  [n1] job 546864980124860417: status succeeded after adoption finished
I200415 14:19:10.834890 17300 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 3.318175036s, 1.29 MiB/s)
I200415 14:19:11.048326 17477 jobs/registry.go:803  [n1] job 546864980188692481: stepping through state succeeded with error <nil>
I200415 14:19:11.088712 17477 jobs/registry.go:958  [n1] job 546864980188692481: status succeeded after adoption finished
I200415 14:19:11.094249 17303 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 3.554068844s, 2.19 MiB/s)
I200415 14:19:11.257889 17905 kv/kvserver/replica_command.go:397  [n1,s1,r47/1:/Table/56/{1-2}] initiating a split of this range at key /Table/56/1/0/1 [r83] (manual)
I200415 14:19:11.979958 17409 jobs/registry.go:803  [n1] job 546864980179320833: stepping through state succeeded with error <nil>
I200415 14:19:11.992278 17409 jobs/registry.go:958  [n1] job 546864980179320833: status succeeded after adoption finished
I200415 14:19:11.992789 17304 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 4.452084997s, 7.14 MiB/s)
I200415 14:19:12.381030 18452 kv/kvserver/replica_command.go:397  [n1,s1,r79/1:/Table/61/{1-2}] initiating a split of this range at key /Table/61/1/0/1/-3001/1 [r84] (manual)
I200415 14:19:13.112451 17419 jobs/registry.go:803  [n1] job 546864980200357889: stepping through state succeeded with error <nil>
I200415 14:19:13.124920 17419 jobs/registry.go:958  [n1] job 546864980200357889: status succeeded after adoption finished
I200415 14:19:13.125338 17305 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 5.585226633s, 3.89 MiB/s)
I200415 14:19:13.125514 16218 util/stop/stopper.go:539  quiescing
W200415 14:19:13.125645 19256 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.82s)
        all_test.go:95: sql: no rows in result set
            importing table new_order
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@c17e37738ed39caa51b107f3a8d1407cecb4b336:

I200526 09:57:53.508700 17311 kv/kvserver/replica_command.go:397  [n1,s1,r69/1:/Table/5{8/1-9}] initiating a split of this range at key /Table/58/2 [r71] (manual)
I200526 09:57:54.363481 16301 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200526 09:57:54.363566 16301 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200526 09:57:54.447818 17311 kv/kvserver/replica_command.go:397  [n1,s1,r71/1:/Table/5{8/2-9}] initiating a split of this range at key /Table/58/3 [r72] (manual)
I200526 09:57:54.483012 17459 jobs/registry.go:961  [n1] job 558421354113630209: status succeeded after adoption finished
I200526 09:57:54.510185 17235 ccl/workloadccl/fixture.go:446  imported 1017 B in district table (10 rows, 0 index entries, took 1.552584818s, 0.00 MiB/s)
I200526 09:57:55.190942 17968 kv/kvserver/replica_command.go:397  [n1,s1,r63/1:/Table/60/{1-2}] initiating a split of this range at key /Table/60/1/0/1/1 [r73] (manual)
I200526 09:57:55.236779 17325 jobs/registry.go:806  [n1] job 558421353998548993: stepping through state succeeded with error <nil>
I200526 09:57:55.348328 17325 jobs/registry.go:961  [n1] job 558421353998548993: status succeeded after adoption finished
I200526 09:57:55.363026 17238 ccl/workloadccl/fixture.go:446  imported 1.5 MiB in order table (30000 rows, 30000 index entries, took 2.405128135s, 0.62 MiB/s)
I200526 09:57:55.751330 17352 jobs/registry.go:806  [n1] job 558421354064773121: stepping through state succeeded with error <nil>
I200526 09:57:55.885137 17352 jobs/registry.go:961  [n1] job 558421354064773121: status succeeded after adoption finished
I200526 09:57:55.905064 17236 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 2.947419365s, 5.96 MiB/s)
I200526 09:57:56.285904 17311 jobs/registry.go:806  [n1] job 558421354017685505: stepping through state succeeded with error <nil>
I200526 09:57:56.317919 17311 jobs/registry.go:961  [n1] job 558421354017685505: status succeeded after adoption finished
I200526 09:57:56.332093 17237 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 3.374301776s, 1.27 MiB/s)
I200526 09:57:56.340993 17308 jobs/registry.go:806  [n1] job 558421354043047937: stepping through state succeeded with error <nil>
I200526 09:57:56.433938 17308 jobs/registry.go:961  [n1] job 558421354043047937: status succeeded after adoption finished
I200526 09:57:56.448438 17240 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 3.490295728s, 2.23 MiB/s)
I200526 09:57:56.537900 18248 kv/kvserver/replica_command.go:397  [n1,s1,r48/1:/Table/59/{1-2}] initiating a split of this range at key /Table/59/1/0/1 [r74] (manual)
I200526 09:57:57.136001 17388 jobs/registry.go:806  [n1] job 558421354080305153: stepping through state succeeded with error <nil>
I200526 09:57:57.150965 17388 jobs/registry.go:961  [n1] job 558421354080305153: status succeeded after adoption finished
I200526 09:57:57.591590 18351 kv/kvserver/replica_command.go:397  [n1,s1,r38/1:/Table/56/{1-2}] initiating a split of this range at key /Table/56/1/0/1/-3001/1 [r75] (manual)
I200526 09:57:58.541569 17261 jobs/registry.go:806  [n1] job 558421353996222465: stepping through state succeeded with error <nil>
I200526 09:57:58.555134 17261 jobs/registry.go:961  [n1] job 558421353996222465: status succeeded after adoption finished
I200526 09:57:58.555813 17242 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 5.598612127s, 3.88 MiB/s)
I200526 09:57:58.555998 14497 util/stop/stopper.go:539  quiescing
W200526 09:57:58.556126 19070 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.94s)
        all_test.go:95: sql: no rows in result set
            importing table stock
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

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

@knz knz unassigned danhhz Jun 4, 2020
@knz
Copy link
Contributor

knz commented Jun 4, 2020

Looking at the code, the IMPORT performed by workload is failing.

cc @dt for triage.

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@92670dd72acad03bd9de54a197d66ef423a90183:

I200608 21:09:36.466280 17630 kv/kvserver/replica_command.go:397  [n1,s1,r67/1:/{Table/61/1-Max}] initiating a split of this range at key /Table/61/2 [r68] (manual)
W200608 21:09:36.817609 18402 kv/kvserver/intentresolver/intent_resolver.go:441  failed to push during intent resolution: failed to push meta={id=b286d103 key=/Table/SystemConfigSpan/Start pri=0.04130029 epo=0 ts=1591650576.697935446,0 min=1591650576.697935446,0 seq=1} lock=true stat=PENDING rts=0,0 wto=false max=0,0
I200608 21:09:36.817716 17475 jobs/registry.go:806  [n1] job 562233918587830273: stepping through state succeeded with error <nil>
I200608 21:09:36.909122 17475 jobs/registry.go:961  [n1] job 562233918587830273: status succeeded after adoption finished
I200608 21:09:36.928076 17361 kv/kvserver/replica_command.go:397  [n1,s1,r33/1:/Table/53/{1-2}] initiating a split of this range at key /Table/53/1/0/1/1 [r69] (manual)
I200608 21:09:36.939031 17369 jobs/registry.go:806  [n1] job 562233918547853313: stepping through state succeeded with error <nil>
I200608 21:09:36.968978 16124 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200608 21:09:36.969388 16124 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200608 21:09:37.018317 17369 jobs/registry.go:961  [n1] job 562233918547853313: status succeeded after adoption finished
I200608 21:09:37.615448 17243 ccl/workloadccl/fixture.go:446  imported 114 KiB in new_order table (9000 rows, 0 index entries, took 2.307896466s, 0.05 MiB/s)
I200608 21:09:37.974759 17228 jobs/registry.go:806  [n1] job 562233918501322753: stepping through state succeeded with error <nil>
I200608 21:09:38.161998 17228 jobs/registry.go:961  [n1] job 562233918501322753: status succeeded after adoption finished
I200608 21:09:38.199722 17240 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 2.892179385s, 6.07 MiB/s)
I200608 21:09:38.994484 17456 jobs/registry.go:806  [n1] job 562233918652022785: stepping through state succeeded with error <nil>
I200608 21:09:39.040443 17456 jobs/registry.go:961  [n1] job 562233918652022785: status succeeded after adoption finished
I200608 21:09:39.062827 17241 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 3.755567793s, 1.14 MiB/s)
I200608 21:09:39.125177 17623 jobs/registry.go:806  [n1] job 562233918605524993: stepping through state succeeded with error <nil>
I200608 21:09:39.164033 17623 jobs/registry.go:961  [n1] job 562233918605524993: status succeeded after adoption finished
I200608 21:09:39.177538 17244 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 3.869022946s, 2.01 MiB/s)
I200608 21:09:39.512545 18239 kv/kvserver/replica_command.go:397  [n1,s1,r67/1:/Table/61/{1-2}] initiating a split of this range at key /Table/61/1/0/1 [r70] (manual)
I200608 21:09:39.790955 17630 jobs/registry.go:806  [n1] job 562233918704582657: stepping through state succeeded with error <nil>
I200608 21:09:39.804125 17630 jobs/registry.go:961  [n1] job 562233918704582657: status succeeded after adoption finished
I200608 21:09:39.804393 17245 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 4.480274235s, 7.09 MiB/s)
I200608 21:09:39.937014 17709 kv/kvserver/replica_command.go:397  [n1,s1,r35/1:/Table/55/{1-2}] initiating a split of this range at key /Table/55/1/0/1/-3001/1 [r71] (manual)
I200608 21:09:40.813165 17327 jobs/registry.go:806  [n1] job 562233918501453825: stepping through state succeeded with error <nil>
I200608 21:09:40.841243 17327 jobs/registry.go:961  [n1] job 562233918501453825: status succeeded after adoption finished
I200608 21:09:40.841696 17246 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 5.534296799s, 3.92 MiB/s)
I200608 21:09:40.841926 15840 util/stop/stopper.go:539  quiescing
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.78s)
        all_test.go:95: sql: no rows in result set
            importing table order
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

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

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@ae7d20e1d4fb65875118eb05d043714c0a1fb08f:

I200613 00:48:48.109257 18408 kv/kvserver/replica_command.go:397  [n1,split,s1,r49/1:/Table/5{8/3-9/1}] initiating a split of this range at key /Table/59 [r66] (zone config)
I200613 00:48:48.227863 17578 jobs/registry.go:961  [n1] job 563409474821423105: status succeeded after adoption finished
I200613 00:48:48.464959 17408 ccl/workloadccl/fixture.go:446  imported 114 KiB in new_order table (9000 rows, 0 index entries, took 1.867333315s, 0.06 MiB/s)
I200613 00:48:48.743427 16549 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200613 00:48:48.743614 16549 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200613 00:48:49.129849 17635 jobs/registry.go:806  [n1] job 563409474794127361: stepping through state succeeded with error <nil>
I200613 00:48:49.140234 17635 jobs/registry.go:961  [n1] job 563409474794127361: status succeeded after adoption finished
I200613 00:48:49.155085 18499 kv/kvserver/replica_command.go:397  [n1,split,s1,r58/1:/Table/5{6/2-7/1}] initiating a split of this range at key /Table/57 [r67] (zone config)
I200613 00:48:49.325056 17621 jobs/registry.go:806  [n1] job 563409474770370561: stepping through state succeeded with error <nil>
I200613 00:48:49.601054 17621 jobs/registry.go:961  [n1] job 563409474770370561: status succeeded after adoption finished
I200613 00:48:49.620346 17406 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 3.022674909s, 1.42 MiB/s)
I200613 00:48:49.854767 18269 kv/kvserver/replica_command.go:397  [n1,s1,r57/1:/Table/56/{1-2}] initiating a split of this range at key /Table/56/1/0/1/1 [r68] (manual)
I200613 00:48:49.858849 17879 kv/kvserver/replica_command.go:397  [n1,s1,r34/1:/Table/59/{1-2}] initiating a split of this range at key /Table/59/1/0/1 [r69] (manual)
I200613 00:48:49.921056 17638 jobs/registry.go:806  [n1] job 563409474772566017: stepping through state succeeded with error <nil>
I200613 00:48:50.051837 17638 jobs/registry.go:961  [n1] job 563409474772566017: status succeeded after adoption finished
I200613 00:48:50.072954 17409 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 3.475213058s, 2.24 MiB/s)
I200613 00:48:50.208104 17603 jobs/registry.go:806  [n1] job 563409474759131137: stepping through state succeeded with error <nil>
I200613 00:48:50.259266 17603 jobs/registry.go:961  [n1] job 563409474759131137: status succeeded after adoption finished
I200613 00:48:50.264729 17405 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 3.667285528s, 4.79 MiB/s)
I200613 00:48:50.556503 18945 kv/kvserver/replica_consistency.go:255  [n1,consistencyChecker,s1,r4/1:/System{/tsd-tse}] triggering stats recomputation to resolve delta of {ContainsEstimates:1450 LastUpdateNanos:1592009326447752276 IntentAge:0 GCBytesAge:0 LiveBytes:-35540 LiveCount:-698 KeyBytes:-34017 KeyCount:-698 ValBytes:-1523 ValCount:-698 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I200613 00:48:50.910916 17666 jobs/registry.go:806  [n1] job 563409474803302401: stepping through state succeeded with error <nil>
I200613 00:48:50.923943 17666 jobs/registry.go:961  [n1] job 563409474803302401: status succeeded after adoption finished
I200613 00:48:50.924166 17506 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 4.326316326s, 7.34 MiB/s)
I200613 00:48:51.226920 18107 kv/kvserver/replica_command.go:397  [n1,s1,r54/1:/Table/54/{1-2}] initiating a split of this range at key /Table/54/1/0/1/-3001/1 [r70] (manual)
I200613 00:48:52.210877 17553 jobs/registry.go:806  [n1] job 563409474774335489: stepping through state succeeded with error <nil>
I200613 00:48:52.221824 17553 jobs/registry.go:961  [n1] job 563409474774335489: status succeeded after adoption finished
I200613 00:48:52.222132 17507 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 5.624736276s, 3.86 MiB/s)
I200613 00:48:52.222672 16505 util/stop/stopper.go:539  quiescing
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.90s)
        all_test.go:95: sql: no rows in result set
            importing table order
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

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

@dt
Copy link
Member

dt commented Jun 16, 2020

@miretskiy any progress on this one? alternatively, I think you mentioned last month that you'd pulled on various loose ends here for awhile without finding any smoking guns, so would it make sense to see if a new pair of eyes help?

@miretskiy
Copy link
Contributor

Still looking. I didn't spend a lot of time on this. Going to give it another go.

@miretskiy
Copy link
Contributor

Having hard time reproing w/ roachprod-stressrace:

56423 runs so far, 0 failures, over 30m55s

@miretskiy
Copy link
Contributor

Not much luck on 20.1 branch either: 30343 runs so far, 0 failures, over 15m40s

@miretskiy
Copy link
Contributor

Previously, I've debugged the same issue, which I though was fixed by #47783

Alas, it appears that's not the case. The failures are much less likely to occur, but they still do occur. I wonder if StartableJob might still be to blame.

@miretskiy
Copy link
Contributor

@dt Having really hard time reproducing; if somebody has desire to take a look at this, i'd appreciate it.

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@9c486c55b8a92cf2f1e441458b7a8c7ee2a55679:

I200630 22:51:33.269114 1924 sql/temporary_schema.go:494  [n1] found 0 temporary schemas
I200630 22:51:33.269181 1924 sql/temporary_schema.go:497  [n1] early exiting temporary schema cleaner as no temporary schemas were found
I200630 22:51:33.269193 1924 sql/temporary_schema.go:498  [n1] completed temporary object cleanup job
I200630 22:51:33.269210 1924 sql/temporary_schema.go:575  [n1] temporary object cleaner next scheduled to run at 2020-06-30 23:21:33.212873121 +0000 UTC
I200630 22:51:33.271723 1969 sql/event_log.go:132  [n1,intExec=set-setting] Event: "set_cluster_setting", target: 0, info: {SettingName:version Value:20.1 User:root}
I200630 22:51:33.309172 2394 sql/event_log.go:132  [n1,intExec=initializeClusterSecret] Event: "set_cluster_setting", target: 0, info: {SettingName:cluster.secret Value:29f4621b-48bc-448a-b085-6c1041d4b477 User:root}
I200630 22:51:33.315746 2500 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 50, info: {DatabaseName:defaultdb Statement:CREATE DATABASE IF NOT EXISTS defaultdb User:root}
I200630 22:51:33.321091 2507 sql/event_log.go:132  [n1,intExec=create-default-db] Event: "create_database", target: 51, info: {DatabaseName:postgres Statement:CREATE DATABASE IF NOT EXISTS postgres User:root}
I200630 22:51:33.342051 1689 server/server.go:1798  [n1] done ensuring all necessary migrations have run
I200630 22:51:33.342159 1689 server/server.go:2040  [n1] serving sql connections
I200630 22:51:33.344995 2646 server/server_update.go:55  [n1] no need to upgrade, cluster already at the newest version
I200630 22:51:33.346861 2648 sqlmigrations/migrations.go:668  [n1] starting wait for upgrade finalization before schema change job migration
I200630 22:51:33.347092 2649 sql/event_log.go:132  [n1] Event: "node_join", target: 1, info: {Descriptor:{NodeID:1 Address:127.0.0.1:37153 Attrs: Locality: ServerVersion:20.1 BuildTag:v20.1.3-19-g9c486c5 StartedAt:1593557493190135384 LocalityAddress:[] ClusterName: SQLAddress:127.0.0.1:33971} ClusterID:ffb22e4f-b85d-43bd-bee2-888ccae5e57d StartedAt:1593557493190135384 LastUp:1593557493190135384}
I200630 22:51:33.347343 2648 sqlmigrations/migrations.go:700  [n1] starting schema change job migration
I200630 22:51:33.351784 2648 sqlmigrations/migrations.go:1124  [schema-change-job-migration] evaluating tables for creating jobs
I200630 22:51:33.351827 2648 sqlmigrations/migrations.go:719  [n1] schema change job migration completed
I200630 22:51:33.365211 2665 sql/event_log.go:132  [n1,client=127.0.0.1:49486,hostssl,user=root] Event: "create_database", target: 52, info: {DatabaseName:d Statement:CREATE DATABASE d User:root}
I200630 22:51:33.366718 1689 ccl/workloadccl/fixture.go:316  starting import of 1 tables
I200630 22:51:33.410129 2753 jobs/registry.go:806  [n1] job 568482507585454081: stepping through state running with error <nil>
I200630 22:51:33.444291 2753 kv/kvserver/replica_command.go:397  [n1,s1,r32/1:/{Table/36-Max}] initiating a split of this range at key /Table/53/1 [r33] (manual)
I200630 22:51:33.456459 2753 kv/kvserver/replica_command.go:397  [n1,s1,r33/1:/{Table/53/1-Max}] initiating a split of this range at key /Table/53/2 [r34] (manual)
I200630 22:51:34.442008 2933 kv/kvserver/replica_command.go:397  [n1,split,s1,r32/1:/Table/{36-53/1}] initiating a split of this range at key /Table/53 [r35] (zone config)
I200630 22:51:34.444194 2753 jobs/registry.go:806  [n1] job 568482507585454081: stepping through state succeeded with error <nil>
I200630 22:51:34.455551 2753 jobs/registry.go:961  [n1] job 568482507585454081: status succeeded after adoption finished
I200630 22:51:34.456038 1689 util/stop/stopper.go:539  quiescing
W200630 22:51:34.456177 2938 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
W200630 22:51:34.464366 2933 kv/txn.go:607  [n1,split,s1,r32/1:/Table/{36-53/1}] failure aborting transaction: node unavailable; try another peer; abort caused by: node unavailable; try another peer
E200630 22:51:34.464681 2933 kv/kvserver/queue.go:1090  [n1,split,s1,r32/1:/Table/{36-53/1}] unable to split [n1,s1,r32/1:/Table/{36-53/1}] at key "/Table/53": split at key /Table/53 failed: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/bulkingest (1.39s)
        all_test.go:95: sql: no rows in result set
            importing table bulkingest
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

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

@miretskiy
Copy link
Contributor

@adityamaru were you able to repro this?

@dt
Copy link
Member

dt commented Jul 20, 2020

@pbardea was looking into another issue where the backup hangs forever trying to send the results to the ch -- i wonder if they're related.

Maybe we should just remove the ch arg from Resume entirely: we can synthesize the results from the job itself, so the statement running a job can ask the registry to run it, then lookup the results. It'd be an extra kv round trip but likely not a big deal for bulk-jobs. We could even optimize it away if the startandrun helper returned the results, since then it could ask the same resumer instance for them which could, in theory, have them cached, but we'd need to be really careful with testing to ensure that that cache didn't hide a bug in the slow path.

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@5b680912ff9026bcd349a2886d969158570cdeab:

I200724 15:20:28.037015 18410 kv/kvserver/replica_command.go:397  [n1,split,s1,r45/1:/Table/6{0/1-1/1}] initiating a split of this range at key /Table/61 [r66] (zone config)
I200724 15:20:28.103060 17624 kv/kvserver/replica_command.go:397  [n1,s1,r59/1:/{Table/61/1-Max}] initiating a split of this range at key /Table/61/2 [r67] (manual)
I200724 15:20:28.354192 17309 kv/kvserver/replica_command.go:397  [n1,s1,r65/1:/Table/5{4/2-5}] initiating a split of this range at key /Table/54/3 [r68] (manual)
I200724 15:20:29.044308 16451 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200724 15:20:29.044482 16451 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200724 15:20:29.101649 17418 jobs/registry.go:806  [n1] job 575188588522110977: stepping through state succeeded with error <nil>
I200724 15:20:29.357266 17418 jobs/registry.go:961  [n1] job 575188588522110977: status succeeded after adoption finished
I200724 15:20:29.407689 17378 ccl/workloadccl/fixture.go:446  imported 1.5 MiB in order table (30000 rows, 30000 index entries, took 2.58238017s, 0.58 MiB/s)
I200724 15:20:29.594109 18010 kv/kvserver/replica_command.go:397  [n1,s1,r33/1:/Table/53/{1-2}] initiating a split of this range at key /Table/53/1/0/1/1 [r69] (manual)
I200724 15:20:29.797014 17414 jobs/registry.go:806  [n1] job 575188588520079361: stepping through state succeeded with error <nil>
I200724 15:20:29.897897 17414 jobs/registry.go:961  [n1] job 575188588520079361: status succeeded after adoption finished
I200724 15:20:29.927987 17380 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 3.084774351s, 2.52 MiB/s)
I200724 15:20:30.394725 17429 jobs/registry.go:806  [n1] job 575188588423741441: stepping through state succeeded with error <nil>
I200724 15:20:30.429605 17429 jobs/registry.go:961  [n1] job 575188588423741441: status succeeded after adoption finished
I200724 15:20:30.446832 17184 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 3.62624808s, 4.84 MiB/s)
I200724 15:20:30.573859 17309 jobs/registry.go:806  [n1] job 575188588430229505: stepping through state succeeded with error <nil>
I200724 15:20:30.704681 17309 jobs/registry.go:961  [n1] job 575188588430229505: status succeeded after adoption finished
I200724 15:20:30.709356 17185 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 3.888576641s, 1.10 MiB/s)
I200724 15:20:31.014562 18218 kv/kvserver/replica_command.go:397  [n1,s1,r35/1:/Table/56/{1-2}] initiating a split of this range at key /Table/56/1/0/1 [r70] (manual)
I200724 15:20:32.006139 17407 jobs/registry.go:806  [n1] job 575188588530827265: stepping through state succeeded with error <nil>
I200724 15:20:32.026053 17407 jobs/registry.go:961  [n1] job 575188588530827265: status succeeded after adoption finished
I200724 15:20:32.026647 17381 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 5.183139926s, 6.13 MiB/s)
I200724 15:20:32.186850 18480 kv/kvserver/replica_command.go:397  [n1,s1,r59/1:/Table/61/{1-2}] initiating a split of this range at key /Table/61/1/0/1/-3001/1 [r71] (manual)
I200724 15:20:33.045662 17624 jobs/registry.go:806  [n1] job 575188588736446465: stepping through state succeeded with error <nil>
I200724 15:20:33.057598 17624 jobs/registry.go:961  [n1] job 575188588736446465: status succeeded after adoption finished
I200724 15:20:33.057894 17382 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 6.202184243s, 3.50 MiB/s)
I200724 15:20:33.058291 16127 util/stop/stopper.go:539  quiescing
W200724 15:20:33.058746 19343 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/tpcc (6.68s)
        all_test.go:95: sql: no rows in result set
            importing table new_order
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@2c11564406e17a3411c56d2488832db705b4107c:

I200805 05:12:59.635370 17214 jobs/registry.go:806  [n1] job 578466539177836545: stepping through state succeeded with error <nil>
I200805 05:13:00.046333 17214 jobs/registry.go:961  [n1] job 578466539177836545: status succeeded after adoption finished
I200805 05:13:00.072552 17221 ccl/workloadccl/fixture.go:446  imported 114 KiB in new_order table (9000 rows, 0 index entries, took 2.112254268s, 0.05 MiB/s)
I200805 05:13:00.204251 16261 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200805 05:13:00.204410 16261 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200805 05:13:00.378101 17312 jobs/registry.go:806  [n1] job 578466539226103809: stepping through state succeeded with error <nil>
I200805 05:13:00.465226 17312 jobs/registry.go:961  [n1] job 578466539226103809: status succeeded after adoption finished
I200805 05:13:00.487475 17219 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 2.527135209s, 1.70 MiB/s)
I200805 05:13:00.601130 17136 jobs/registry.go:806  [n1] job 578466539298226177: stepping through state succeeded with error <nil>
I200805 05:13:00.662539 17240 jobs/registry.go:806  [n1] job 578466539229708289: stepping through state succeeded with error <nil>
I200805 05:13:00.683374 17136 jobs/registry.go:961  [n1] job 578466539298226177: status succeeded after adoption finished
I200805 05:13:00.762806 17240 jobs/registry.go:961  [n1] job 578466539229708289: status succeeded after adoption finished
I200805 05:13:00.819129 17222 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 2.858705937s, 2.72 MiB/s)
I200805 05:13:00.939373 17735 kv/kvserver/replica_command.go:397  [n1,s1,r43/1:/Table/53/{1-2}] initiating a split of this range at key /Table/53/1/0/1/1 [r63] (manual)
I200805 05:13:01.435566 17164 jobs/registry.go:806  [n1] job 578466539121901569: stepping through state succeeded with error <nil>
I200805 05:13:01.453901 17164 jobs/registry.go:961  [n1] job 578466539121901569: status succeeded after adoption finished
I200805 05:13:01.459960 17218 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 3.500065288s, 5.02 MiB/s)
I200805 05:13:01.652968 17758 kv/kvserver/replica_command.go:397  [n1,s1,r50/1:/Table/60/{1-2}] initiating a split of this range at key /Table/60/1/0/1 [r64] (manual)
I200805 05:13:02.186905 17275 jobs/registry.go:806  [n1] job 578466539234164737: stepping through state succeeded with error <nil>
I200805 05:13:02.196704 17275 jobs/registry.go:961  [n1] job 578466539234164737: status succeeded after adoption finished
I200805 05:13:02.197001 17223 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 4.236494771s, 7.50 MiB/s)
I200805 05:13:02.519108 17784 kv/kvserver/replica_command.go:397  [n1,s1,r51/1:/Table/54/{1-2}] initiating a split of this range at key /Table/54/1/0/1/-3001/1 [r65] (manual)
I200805 05:13:02.974209 18097 kv/kvserver/replica_consistency.go:246  [n1,consistencyChecker,s1,r4/1:/System{/tsd-tse}] triggering stats recomputation to resolve delta of {ContainsEstimates:1450 LastUpdateNanos:1596604377857584018 IntentAge:0 GCBytesAge:0 LiveBytes:-35567 LiveCount:-698 KeyBytes:-34017 KeyCount:-698 ValBytes:-1550 ValCount:-698 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I200805 05:13:03.081540 17257 jobs/registry.go:806  [n1] job 578466539115577345: stepping through state succeeded with error <nil>
I200805 05:13:03.092356 17257 jobs/registry.go:961  [n1] job 578466539115577345: status succeeded after adoption finished
I200805 05:13:03.092658 17224 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 5.132859652s, 4.23 MiB/s)
I200805 05:13:03.092922 16206 util/stop/stopper.go:539  quiescing
W200805 05:13:03.093048 19197 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.30s)
        all_test.go:95: sql: no rows in result set
            importing table order
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@ajwerner
Copy link
Contributor

ajwerner commented Aug 7, 2020

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@be8c07155e52cfea32f7107a027e64a118e6d8f4:

I200807 05:14:17.700443 18246 kv/kvserver/split_queue.go:149  [n1,split,s1,r57/1:/Table/5{4/2-5/1}] split saw concurrent descriptor modification; maybe retrying
I200807 05:14:17.700610 18442 kv/kvserver/replica_command.go:397  [n1,split,s1,r57/1:/Table/5{4/2-5/1}] initiating a split of this range at key /Table/55 [r71] (zone config)
I200807 05:14:17.727906 16425 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200807 05:14:17.728066 16425 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200807 05:14:17.777822 17438 jobs/registry.go:806  [n1] job 579033025829928961: stepping through state succeeded with error <nil>
I200807 05:14:17.792812 17466 jobs/registry.go:806  [n1] job 579033025827045377: stepping through state succeeded with error <nil>
I200807 05:14:17.882233 17438 jobs/registry.go:961  [n1] job 579033025829928961: status succeeded after adoption finished
I200807 05:14:17.947393 17358 ccl/workloadccl/fixture.go:446  imported 53 B in warehouse table (1 rows, 0 index entries, took 1.968052568s, 0.00 MiB/s)
I200807 05:14:18.023441 18233 kv/kvserver/replica_consistency.go:246  [n1,consistencyChecker,s1,r4/1:/System{/tsd-tse}] triggering stats recomputation to resolve delta of {ContainsEstimates:1450 LastUpdateNanos:1596777255887633625 IntentAge:0 GCBytesAge:0 LiveBytes:-35567 LiveCount:-698 KeyBytes:-34017 KeyCount:-698 ValBytes:-1550 ValCount:-698 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0}
I200807 05:14:18.096181 17466 jobs/registry.go:961  [n1] job 579033025827045377: status succeeded after adoption finished
I200807 05:14:18.132894 17364 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 2.152578868s, 3.61 MiB/s)
I200807 05:14:18.715216 17490 jobs/registry.go:806  [n1] job 579033025812070401: stepping through state succeeded with error <nil>
I200807 05:14:18.783656 17490 jobs/registry.go:961  [n1] job 579033025812070401: status succeeded after adoption finished
I200807 05:14:18.793860 17361 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 2.8139653s, 1.52 MiB/s)
I200807 05:14:18.952920 17971 kv/kvserver/replica_command.go:397  [n1,s1,r46/1:/Table/56/{1-2}] initiating a split of this range at key /Table/56/1/0/1 [r72] (manual)
I200807 05:14:18.997150 18157 kv/kvserver/replica_command.go:397  [n1,s1,r65/1:/Table/61/{1-2}] initiating a split of this range at key /Table/61/1/0/1/1 [r73] (manual)
I200807 05:14:19.317357 17464 jobs/registry.go:806  [n1] job 579033025879408641: stepping through state succeeded with error <nil>
I200807 05:14:19.427229 17464 jobs/registry.go:961  [n1] job 579033025879408641: status succeeded after adoption finished
I200807 05:14:19.427927 17360 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 3.448162453s, 5.09 MiB/s)
I200807 05:14:19.541270 16409 jobs/registry.go:806  [n1] job 579033025881571329: stepping through state succeeded with error <nil>
I200807 05:14:19.555221 16409 jobs/registry.go:961  [n1] job 579033025881571329: status succeeded after adoption finished
I200807 05:14:19.555602 17365 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 3.575181966s, 8.89 MiB/s)
I200807 05:14:19.980570 18174 kv/kvserver/replica_command.go:397  [n1,s1,r50/1:/Table/60/{1-2}] initiating a split of this range at key /Table/60/1/0/1/-3001/1 [r74] (manual)
I200807 05:14:20.825820 17498 jobs/registry.go:806  [n1] job 579033025826521089: stepping through state succeeded with error <nil>
I200807 05:14:20.837364 17498 jobs/registry.go:961  [n1] job 579033025826521089: status succeeded after adoption finished
I200807 05:14:20.837648 17366 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 4.858372206s, 4.47 MiB/s)
I200807 05:14:20.837875 16256 util/stop/stopper.go:539  quiescing
W200807 05:14:20.838014 19197 kv/kvserver/intentresolver/intent_resolver.go:745  failed to gc transaction record: could not GC completed transaction anchored at /Table/SystemConfigSpan/Start: node unavailable; try another peer
    --- FAIL: TestAllRegisteredImportFixture/tpcc (5.18s)
        all_test.go:95: sql: no rows in result set
            importing table district
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@cockroach-teamcity
Copy link
Member Author

(ccl/workloadccl/allccl).TestAllRegisteredImportFixture failed on release-20.1@c7fbbbeff8aca92d347be88db91ef21f8c1cb80c:

I200902 05:12:46.386953 18291 jobs/registry.go:961  [n1] job 586393731568631809: status succeeded after adoption finished
I200902 05:12:46.400171 18180 ccl/workloadccl/fixture.go:446  imported 1017 B in district table (10 rows, 0 index entries, took 1.270791442s, 0.00 MiB/s)
I200902 05:12:46.418105 19210 kv/kvserver/replica_command.go:397  [n1,split,s1,r67/1:/Table/6{0/2-1/1}] initiating a split of this range at key /Table/61 [r72] (zone config)
I200902 05:12:46.427407 19196 kv/kvserver/split_queue.go:149  [n1,split,s1,r57/1:/Table/60/{1-2}] split saw concurrent descriptor modification; maybe retrying
I200902 05:12:47.137852 18308 jobs/registry.go:806  [n1] job 586393731609690113: stepping through state succeeded with error <nil>
I200902 05:12:47.279684 17224 gossip/gossip.go:1527  [n1] node has connected to cluster via gossip
I200902 05:12:47.279887 17224 kv/kvserver/stores.go:266  [n1] wrote 0 node addresses to persistent storage
I200902 05:12:47.348327 18308 jobs/registry.go:961  [n1] job 586393731609690113: status succeeded after adoption finished
I200902 05:12:47.358594 18185 ccl/workloadccl/fixture.go:446  imported 7.8 MiB in item table (100000 rows, 0 index entries, took 2.229037687s, 3.49 MiB/s)
I200902 05:12:47.360595 18063 jobs/registry.go:806  [n1] job 586393731570040833: stepping through state succeeded with error <nil>
I200902 05:12:47.434654 18063 jobs/registry.go:961  [n1] job 586393731570040833: status succeeded after adoption finished
I200902 05:12:47.440957 18182 ccl/workloadccl/fixture.go:446  imported 4.3 MiB in history table (30000 rows, 60000 index entries, took 2.311643446s, 1.85 MiB/s)
I200902 05:12:47.459104 18551 kv/kvserver/replica_command.go:397  [n1,s1,r35/1:/Table/57/{1-2}] initiating a split of this range at key /Table/57/1/0/1 [r73] (manual)
I200902 05:12:47.555395 10607 jobs/registry.go:806  [n1] job 586393731666083841: stepping through state succeeded with error <nil>
I200902 05:12:47.570637 10607 jobs/registry.go:961  [n1] job 586393731666083841: status succeeded after adoption finished
I200902 05:12:47.575352 18183 ccl/workloadccl/fixture.go:446  imported 1.5 MiB in order table (30000 rows, 30000 index entries, took 2.4458042s, 0.61 MiB/s)
I200902 05:12:47.812294 19083 kv/kvserver/replica_command.go:397  [n1,s1,r56/1:/Table/58/{1-2}] initiating a split of this range at key /Table/58/1/0/1/1 [r74] (manual)
I200902 05:12:47.958420 5950 jobs/registry.go:806  [n1] job 586393731586326529: stepping through state succeeded with error <nil>
I200902 05:12:47.969210 18156 jobs/registry.go:806  [n1] job 586393731572662273: stepping through state succeeded with error <nil>
I200902 05:12:47.970522 5950 jobs/registry.go:961  [n1] job 586393731586326529: status succeeded after adoption finished
I200902 05:12:47.971436 18181 ccl/workloadccl/fixture.go:446  imported 18 MiB in customer table (30000 rows, 30000 index entries, took 2.842130327s, 6.18 MiB/s)
I200902 05:12:47.984378 18156 jobs/registry.go:961  [n1] job 586393731572662273: status succeeded after adoption finished
I200902 05:12:47.984731 18186 ccl/workloadccl/fixture.go:446  imported 32 MiB in stock table (100000 rows, 100000 index entries, took 2.854937095s, 11.13 MiB/s)
I200902 05:12:48.334168 18837 kv/kvserver/replica_command.go:397  [n1,s1,r47/1:/Table/59/{1-2}] initiating a split of this range at key /Table/59/1/0/1/-3001/1 [r75] (manual)
I200902 05:12:49.221307 18266 jobs/registry.go:806  [n1] job 586393731657859073: stepping through state succeeded with error <nil>
I200902 05:12:49.239377 18266 jobs/registry.go:961  [n1] job 586393731657859073: status succeeded after adoption finished
I200902 05:12:49.239644 18187 ccl/workloadccl/fixture.go:446  imported 22 MiB in order_line table (300343 rows, 300343 index entries, took 4.110331359s, 5.28 MiB/s)
I200902 05:12:49.239891 17164 util/stop/stopper.go:539  quiescing
    --- FAIL: TestAllRegisteredImportFixture/tpcc (4.34s)
        all_test.go:95: sql: no rows in result set
            importing table warehouse
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:382
            github.com/cockroachdb/cockroach/pkg/util/ctxgroup.Group.GoCtx.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/util/ctxgroup/ctxgroup.go:166
            github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup.(*Group).Go.func1
            	/go/src/github.com/cockroachdb/cockroach/vendor/golang.org/x/sync/errgroup/errgroup.go:57
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357
            importing fixture
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl.ImportDataLoader.InitialDataLoad
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/fixture.go:322
            github.com/cockroachdb/cockroach/pkg/workload/workloadsql.Setup
            	/go/src/github.com/cockroachdb/cockroach/pkg/workload/workloadsql/workloadsql.go:39
            github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl.TestAllRegisteredImportFixture.func1
            	/go/src/github.com/cockroachdb/cockroach/pkg/ccl/workloadccl/allccl/all_test.go:94
            testing.tRunner
            	/usr/local/go/src/testing/testing.go:909
            runtime.goexit
            	/usr/local/go/src/runtime/asm_amd64.s:1357

More

Parameters:

  • GOFLAGS=-json
make stressrace TESTS=TestAllRegisteredImportFixture PKG=./pkg/ccl/workloadccl/allccl TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Related:

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

@miretskiy
Copy link
Contributor

I don't know if it's worth keeping this bug around open. We have hard time repro-ing it, and it hasn't failed for almost 2 months.

@adityamaru
Copy link
Contributor

This is consistently flaking on the PR trying to pin roachprod, workload, and roachtest to release 20.1 - #55892

It doesn't fail locally though.

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.
Projects
None yet
Development

No branches or pull requests

7 participants