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

bench/rttanalysis: TestBenchmarkExpectation failed #73168

Closed
cockroach-teamcity opened this issue Nov 25, 2021 · 2 comments
Closed

bench/rttanalysis: TestBenchmarkExpectation failed #73168

cockroach-teamcity opened this issue Nov 25, 2021 · 2 comments
Assignees
Labels
C-test-failure Broken test (automatically or manually discovered). O-robot Originated from a bot.

Comments

@cockroach-teamcity
Copy link
Member

bench/rttanalysis.TestBenchmarkExpectation failed with artifacts on release-21.2 @ 2a312d6a67ce43d94b346f632437a89357e85097:

=== RUN   TestBenchmarkExpectation
    validate_benchmark_data.go:124: /go/src/github.com/cockroachdb/cockroach/artifacts/go-build3304493664/b1017/rttanalysis.test --test.run=^$ --test.bench=BenchmarkAlterTableAddColumn --test.benchtime=1x --test.v
I211125 16:40:24.864690 1 (gostd) rand.go:92  [-] 1  random seed: 6089728969098417929
goos: linux
goarch: amd64
pkg: github.com/cockroachdb/cockroach/pkg/bench/rttanalysis
cpu: Intel(R) Xeon(R) CPU @ 2.30GHz
BenchmarkAlterTableAddColumn
BenchmarkAlterTableAddColumn/alter_table_add_1_column
    test_log_scope.go:79: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logBenchmarkAlterTableAddColumn_alter_table_add_1_column148383699
    test_log_scope.go:80: use -show-logs to present logs inline
    test_log_scope.go:79: test logs captured to: /go/src/github.com/cockroachdb/cockroach/artifacts/logBenchmarkAlterTableAddColumn_alter_table_add_1_column705432957
    test_log_scope.go:80: use -show-logs to present logs inline
    rtt_analysis_bench.go:131: -- test log scope end --
    test_log_scope.go:410: unlinkat /go/src/github.com/cockroachdb/cockroach/artifacts/logBenchmarkAlterTableAddColumn_alter_table_add_1_column705432957: directory not empty
    rtt_analysis_bench.go:74: -- test log scope end --
test logs left over in: /go/src/github.com/cockroachdb/cockroach/artifacts/logBenchmarkAlterTableAddColumn_alter_table_add_1_column148383699
--- FAIL: TestBenchmarkExpectation (6.09s)
Reproduce

To reproduce, try:

make stressrace TESTS=TestBenchmarkExpectation PKG=./pkg/bench/rttanalysis TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

/cc @cockroachdb/sql-experience pawalt

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

bench/rttanalysis.TestBenchmarkExpectation failed with artifacts on release-21.2 @ f963a1eb6daa99bd5fd2c43771773473cdf361f7:

          1924.159ms      0.285ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\271\223\341\371\037Yk\320\022\360\251u$\267\345@\203\207\263\001\235\265\037+r\000\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_tim..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1924.314ms      0.155ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\271\223\341\371\037Yk\320\022\360\251u$\267\345@\203\207\263\001\235\265\037+r\000\001\212\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1924.435ms      0.121ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\271\223\341\371\037Yk\320\022\360\251u$\267\345@\203\207\263\001\235\265\037+r\000\001\213\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1924.734ms      0.299ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\271\223\341\371\037Yk\320\022\360\251u$\267\345@\203\207\263\001\235\265\037+r\000\001\214\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1924.880ms      0.146ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\271\223\341\371\037Yk\320\022\360\251u$\267\345@\203\207\263\001\235\265\037+r\000\001\215\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1924.944ms      0.065ms                    event:kv/kvserver/replica_read.go:179 [n1,s1,r8/1:/Table/1{2-3}] read completed
          1920.181ms      0.103ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] querying next range at /Table/15/1/719197207034396673/0
          1920.358ms      0.178ms            event:kv/kvclient/kvcoord/dist_sender.go:1916 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] r11: sending batch 12 QueryIntent to (n1,s1):1
          1920.395ms      0.036ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] sending request to local client
          1920.405ms      0.010ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:1b3e524a-2830-4a6d-9130-07d9c4202911
          1920.435ms      0.031ms                event:server/node.go:907 [n1] node received request: 12 QueryIntent
          1920.756ms      0.320ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing QueryIntent [/Table/15/1/719197207034396673/0,/Min), QueryIntent [/Table/15/1/719197207034396673/1/1,/Min), QueryIntent [/Table/15/1/719197212515729409/0,/Min), QueryIntent [/Table/15/1/719197212515729409/1/1,/Min), QueryIntent [/Table/15/1/719197212515729409/2/1,/Min), QueryIntent [/Table/15/2/"running"/2021-12-15T07:06:09.525954Z/719197207034396673/0,/Min), QueryIntent [/Table/15/2/"running"/2021-12-15T07:06:09.525954Z/719197212515729409/0,/Min), QueryIntent [/Table/15/3/NULL/NULL/719197207034396673/0,/Min), QueryIntent [/Table/15/3/NULL/NULL/719197212515729409/0,/Min), QueryIntent [/Table/15/4/NULL/"running"/2021-12-15T07:06:09.525954Z/719197207034396673/0,/Min), QueryIntent [/Table/15/4/"\x88\x9a\xb0\x1e8\x17@W\x9d\xaf\xb4\xa6\xd3\xddB@"/"running"/2021-12-15T07:06:09.525954Z/719197212515729409/0,/Min), QueryIntent [/Table/15/4/"\x88\x9a\xb0\x1e8\x17@W\x9d\xaf\xb4\xa6\xd3\xddB@"/"running"/2021-12-15T07:06:09.525954Z/719197212515729409/2/1,/Min), [txn: 1b3e524a]
          1920.807ms      0.052ms                event:kv/kvserver/replica_send.go:101 [n1,s1,r11/1:/Table/1{5-6}] read-only path
          1920.852ms      0.045ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r11/1:/Table/1{5-6}] sequencing request
          1920.884ms      0.031ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r11/1:/Table/1{5-6}] acquiring latches
          1920.944ms      0.061ms                event:kv/kvserver/replica_read.go:243 [n1,s1,r11/1:/Table/1{5-6}] executing read-only batch
          1921.168ms      0.224ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\t\373\032\014\240\275\000\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:1 > error_if..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1921.404ms      0.236ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\t\373\032\014\240\275\000\001\211\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:2 > erro..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1921.556ms      0.151ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\t\373\032\r\347s\200\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:12 > error_if_mis..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1921.761ms      0.205ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\t\373\032\r\347s\200\001\211\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:13 > error_if..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1921.899ms      0.138ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\t\373\032\r\347s\200\001\212\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:14 > error_if..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.033ms      0.134ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\212\022running\000\001\024\371a\271\223\341\371\037Yk\320\375\t\373\032\014\240\275\000\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:163955..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.169ms      0.136ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\212\022running\000\001\024\371a\271\223\341\371\037Yk\320\375\t\373\032\r\347s\200\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:16395519695..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.495ms      0.326ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\t\373\032\014\240\275\000\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:4 > ..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.659ms      0.164ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\t\373\032\r\347s\200\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:16 > erro..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.793ms      0.134ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\000\022running\000\001\024\371a\271\223\341\371\037Yk\320\375\t\373\032\014\240\275\000\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:16..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1922.971ms      0.178ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\210\232\260\0368\027@W\235\257\264\246\323\335B@\000\001\022running\000\001\024\371a\271\223\341\371\037Yk\320\375\t\373\032\r\347s\200\001\210" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_ti..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1923.134ms      0.163ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\210\232\260\0368\027@W\235\257\264\246\323\335B@\000\001\022running\000\001\024\371a\271\223\341\371\037Yk\320\375\t\373\032\r\347s\200\001\212\211" > txn:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wal..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=0} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<> found_intent:true , err=<nil>
          1923.176ms      0.042ms                event:kv/kvserver/replica_read.go:179 [n1,s1,r11/1:/Table/1{5-6}] read completed
          1931.388ms     10.994ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] querying next range at /Table/SystemConfigSpan/Start
          1931.454ms      0.066ms            event:kv/kvclient/kvcoord/dist_sender.go:1916 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] r6: sending batch 1 EndTxn to (n1,s1):1
          1931.478ms      0.024ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:34258,hostssl,user=root,txn=1b3e524a] sending request to local client
          1931.489ms      0.011ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:1b3e524a-2830-4a6d-9130-07d9c4202911
          1931.517ms      0.028ms                event:server/node.go:907 [n1] node received request: 1 EndTxn
          1931.568ms      0.051ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing EndTxn(commit modified-span (system-config)) [/Table/SystemConfigSpan/Start], [txn: 1b3e524a]
          1931.592ms      0.024ms                event:kv/kvserver/replica_send.go:105 [n1,s1,r6/1:/Table/{SystemCon…-11}] read-write path
          1931.649ms      0.057ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r6/1:/Table/{SystemCon…-11}] sequencing request
          1931.679ms      0.030ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r6/1:/Table/{SystemCon…-11}] acquiring latches
          1931.741ms      0.062ms                event:kv/kvserver/replica_write.go:144 [n1,s1,r6/1:/Table/{SystemCon…-11}] applied timestamp cache
          1931.771ms      0.030ms                event:kv/kvserver/replica_write.go:436 [n1,s1,r6/1:/Table/{SystemCon…-11}] executing read-write batch
          1932.855ms      1.085ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated EndTxn command header:<key:"\210" sequence:19 > commit:true deadline:<wall_time:1639552267496645329 > internal_commit_trigger:<modified_span_trigger:<system_config_span:true > > lock_spans:<key:"\213\211\275\212\211" > lock_spans:<key:"\224\211\024\371a\271\223\341\37..., txn="sql txn" meta={id=1b3e524a key=/Table/SystemConfigSpan/Start pri=0.05301409 epo=0 ts=1639551969.525953955,0 min=1639551969.525953955,0 seq=19} lock=true stat=PENDING rts=1639551969.525953955,0 wto=false gul=1639551970.025953955,0 : resp=header:<txn:<meta:<id:1b3e524a-2830-4a6d-9130-07d9c4202911 key:"\210" write_timestamp:<wall_time:1639551969525953955 > min_timestamp:<wall_time:1639551969525953955 > priority:1138469 sequence:19 > status:COMMITTED last_heartbeat:<wall_time:1639551970683..., err=<nil>
          1932.921ms      0.066ms                event:kv/kvserver/replica_raft.go:90 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated request
          2020.616ms    231.681ms    event:util/log/event_log.go:32 [n1,client=127.0.0.1:34258,hostssl,user=root] Structured entry: {"Timestamp":1639551969525953955,"EventType":"truncate_table","Statement":"TRUNCATE TABLE bench.public.t","Tag":"TRUNCATE","User":"root","DescriptorID":53,"TableName":"bench.public.t"}
          2020.703ms      0.087ms    event:sql/catalog/descs/leased_descriptors.go:235 [n1,client=127.0.0.1:34258,hostssl,user=root] releasing 0 descriptors
          2020.749ms      0.046ms    event:sql/conn_executor_exec.go:1841 [n1,client=127.0.0.1:34258,hostssl,user=root] AutoCommit. err: <nil>
        
        (above trace from test Truncate/truncate_2_column_0_rows. got 24, expected 23)
        --- FAIL: TestBenchmarkExpectation/Truncate/truncate_2_column_0_rows (7.49s)
=== RUN   TestBenchmarkExpectation/Truncate
    --- FAIL: TestBenchmarkExpectation/Truncate (11.03s)
Reproduce

To reproduce, try:

make stressrace TESTS=TestBenchmarkExpectation PKG=./pkg/bench/rttanalysis TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

/cc @cockroachdb/sql-schema ajwerner

This test on roachdash | Improve this report!

@cockroach-teamcity
Copy link
Member Author

bench/rttanalysis.TestBenchmarkExpectation failed with artifacts on release-21.2 @ b4a27f3634e3e41dc3966214cf05ff6870c055c5:

           853.344ms      0.098ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\336:\362\371\030^\305\000\0227F\360!\203\244F1\202\353\222\356\030is\346\000\001\212\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.444ms      0.101ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\336:\362\371\030^\305\000\0227F\360!\203\244F1\202\353\222\356\030is\346\000\001\213\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.530ms      0.086ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\336:\362\371\030^\305\000\0227F\360!\203\244F1\202\353\222\356\030is\346\000\001\214\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.616ms      0.086ms                    event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371a\336:\362\371\030^\305\000\0227F\360!\203\244F1\202\353\222\356\030is\346\000\001\215\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.640ms      0.024ms                    event:kv/kvserver/replica_read.go:179 [n1,s1,r8/1:/Table/1{2-3}] read completed
           830.812ms      0.030ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] querying next range at /Table/15/1/727068293243142145/0
           830.861ms      0.049ms            event:kv/kvclient/kvcoord/dist_sender.go:1916 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] r11: sending batch 12 QueryIntent to (n1,s1):1
           830.879ms      0.018ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] sending request to local client
           830.883ms      0.004ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da
           830.898ms      0.015ms                event:server/node.go:907 [n1] node received request: 12 QueryIntent
           831.124ms      0.226ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing QueryIntent [/Table/15/1/727068293243142145/0,/Min), QueryIntent [/Table/15/1/727068293243142145/1/1,/Min), QueryIntent [/Table/15/1/727068295837777921/0,/Min), QueryIntent [/Table/15/1/727068295837777921/1/1,/Min), QueryIntent [/Table/15/1/727068295837777921/2/1,/Min), QueryIntent [/Table/15/2/"running"/2022-01-12T02:20:34.408864Z/727068293243142145/0,/Min), QueryIntent [/Table/15/2/"running"/2022-01-12T02:20:34.408864Z/727068295837777921/0,/Min), QueryIntent [/Table/15/3/NULL/NULL/727068293243142145/0,/Min), QueryIntent [/Table/15/3/NULL/NULL/727068295837777921/0,/Min), QueryIntent [/Table/15/4/NULL/"running"/2022-01-12T02:20:34.408864Z/727068293243142145/0,/Min), QueryIntent [/Table/15/4/"\x95-\x9a\x17:\xccMn\x9c\b\xccP\x87\xaa\xc5^"/"running"/2022-01-12T02:20:34.408864Z/727068295837777921/0,/Min), QueryIntent [/Table/15/4/"\x95-\x9a\x17:\xccMn\x9c\b\xccP\x87\xaa\xc5^"/"running"/2022-01-12T02:20:34.408864Z/727068295837777921/2/1,/Min), [txn: eb9d61a6]
           831.147ms      0.023ms                event:kv/kvserver/replica_send.go:101 [n1,s1,r11/1:/Table/1{5-6}] read-only path
           831.172ms      0.025ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r11/1:/Table/1{5-6}] sequencing request
           831.187ms      0.015ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r11/1:/Table/1{5-6}] acquiring latches
           831.223ms      0.037ms                event:kv/kvserver/spanlatch/manager.go:517 [n1,s1,r11/1:/Table/1{5-6}] waiting to acquire read latch /Table/15/1/727068295837777921/0@0,0, held by write latch /Table/15/1/727068295837777921/[email protected],0
           853.704ms     22.481ms                event:kv/kvserver/replica_read.go:243 [n1,s1,r11/1:/Table/1{5-6}] executing read-only batch
           853.822ms      0.118ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\027\020\302\2625\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:1 > error_if_mis..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.900ms      0.078ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\027\020\302\2625\000\001\211\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:2 > error_if..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           853.980ms      0.080ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\027\020\303L\334\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:12 > error_if_mi..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.068ms      0.088ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\027\020\303L\334\000\001\211\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:13 > error_i..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.140ms      0.072ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\027\020\303L\334\000\001\212\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:14 > error_i..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.219ms      0.079ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\212\022running\000\001\024\371a\336:\362\371\030^\305\000\375\n\027\020\302\2625\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:164195403..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.298ms      0.079ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\212\022running\000\001\024\371a\336:\362\371\030^\305\000\375\n\027\020\303L\334\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:164195403..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.403ms      0.105ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\n\027\020\302\2625\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:4 > erro..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.485ms      0.083ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\n\027\020\303L\334\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:16 > err..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.571ms      0.086ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\000\022running\000\001\024\371a\336:\362\371\030^\305\000\375\n\027\020\302\2625\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:16419..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.661ms      0.090ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\225-\232\027:\314Mn\234\010\314P\207\252\305^\000\001\022running\000\001\024\371a\336:\362\371\030^\305\000\375\n\027\020\303L\334\000\001\210" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_tim..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.743ms      0.083ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\225-\232\027:\314Mn\234\010\314P\207\252\305^\000\001\022running\000\001\024\371a\336:\362\371\030^\305\000\375\n\027\020\303L\334\000\001\212\211" > txn:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=0} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<> found_intent:true , err=<nil>
           854.769ms      0.026ms                event:kv/kvserver/replica_read.go:179 [n1,s1,r11/1:/Table/1{5-6}] read completed
           854.817ms     23.938ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] querying next range at /Table/SystemConfigSpan/Start
           854.865ms      0.048ms            event:kv/kvclient/kvcoord/dist_sender.go:1916 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] r6: sending batch 1 EndTxn to (n1,s1):1
           854.882ms      0.017ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:51270,hostssl,user=root,txn=eb9d61a6] sending request to local client
           854.890ms      0.009ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da
           854.910ms      0.019ms                event:server/node.go:907 [n1] node received request: 1 EndTxn
           854.949ms      0.039ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing EndTxn(commit modified-span (system-config)) [/Table/SystemConfigSpan/Start], [txn: eb9d61a6]
           854.974ms      0.025ms                event:kv/kvserver/replica_send.go:105 [n1,s1,r6/1:/Table/{SystemCon…-11}] read-write path
           855.020ms      0.046ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r6/1:/Table/{SystemCon…-11}] sequencing request
           855.037ms      0.017ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r6/1:/Table/{SystemCon…-11}] acquiring latches
           855.071ms      0.034ms                event:kv/kvserver/replica_write.go:144 [n1,s1,r6/1:/Table/{SystemCon…-11}] applied timestamp cache
           855.090ms      0.019ms                event:kv/kvserver/replica_write.go:436 [n1,s1,r6/1:/Table/{SystemCon…-11}] executing read-write batch
           855.607ms      0.517ms                event:kv/kvserver/replica_evaluate.go:521 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated EndTxn command header:<key:"\210" sequence:19 > commit:true deadline:<wall_time:1641954326932499558 > internal_commit_trigger:<modified_span_trigger:<system_config_span:true > > lock_spans:<key:"\213\211\275\212\211" > lock_spans:<key:"\224\211\024\371a\336:\362\371\0..., txn="sql txn" meta={id=eb9d61a6 key=/Table/SystemConfigSpan/Start pri=0.01642397 epo=0 ts=1641954034.408864235,0 min=1641954034.408864235,0 seq=19} lock=true stat=PENDING rts=1641954034.408864235,0 wto=false gul=1641954034.908864235,0 : resp=header:<txn:<meta:<id:eb9d61a6-5c80-4f9b-b256-5f2e4f32e5da key:"\210" write_timestamp:<wall_time:1641954034408864235 > min_timestamp:<wall_time:1641954034408864235 > priority:352702 sequence:19 > name:"sql txn" status:COMMITTED last_heartbeat:<wall_time..., err=<nil>
           855.645ms      0.038ms                event:kv/kvserver/replica_raft.go:90 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated request
           860.562ms     40.006ms    event:util/log/event_log.go:32 [n1,client=127.0.0.1:51270,hostssl,user=root] Structured entry: {"Timestamp":1641954034408864235,"EventType":"truncate_table","Statement":"TRUNCATE TABLE bench.public.t","Tag":"TRUNCATE","User":"root","DescriptorID":53,"TableName":"bench.public.t"}
           860.598ms      0.035ms    event:sql/catalog/descs/leased_descriptors.go:234 [n1,client=127.0.0.1:51270,hostssl,user=root] releasing 0 descriptors
           860.621ms      0.023ms    event:sql/conn_executor_exec.go:1842 [n1,client=127.0.0.1:51270,hostssl,user=root] AutoCommit. err: <nil>
        
        (above trace from test Truncate/truncate_2_column_0_rows. got 24, expected 23)
        --- FAIL: TestBenchmarkExpectation/Truncate/truncate_2_column_0_rows (6.50s)
=== RUN   TestBenchmarkExpectation/Truncate
    --- FAIL: TestBenchmarkExpectation/Truncate (13.60s)
Reproduce

To reproduce, try:

make stressrace TESTS=TestBenchmarkExpectation PKG=./pkg/bench/rttanalysis TESTTIMEOUT=5m STRESSFLAGS='-timeout 5m' 2>&1

Parameters in this failure:

  • GOFLAGS=-json

Same failure on other branches

/cc @cockroachdb/sql-schema ajwerner

This test on roachdash | Improve this report!

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

2 participants