cockroachdb / cockroach

CockroachDB — the cloud native, distributed SQL database designed for high availability, effortless scale, and control over data placement.
https://www.cockroachlabs.com
Other
30.1k stars 3.8k forks source link

bench/rttanalysis: TestBenchmarkExpectation failed #81370

Closed cockroach-teamcity closed 2 years ago

cockroach-teamcity commented 2 years ago

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

           389.006ms      0.130ms                    event:kv/kvserver/store_send.go:157 [n1,s1] executing QueryIntent [/Table/12/1/2022-05-17T14:15:36.541845Z/"\xa5\xd9(JW]Ny\xb1,\x1f\x95\x0e'\xf1g"/0,/Min), QueryIntent [/Table/12/1/2022-05-17T14:15:36.541845Z/"\xa5\xd9(JW]Ny\xb1,\x1f\x95\x0e'\xf1g"/2/1,/Min), QueryIntent [/Table/12/1/2022-05-17T14:15:36.541845Z/"\xa5\xd9(JW]Ny\xb1,\x1f\x95\x0e'\xf1g"/3/1,/Min), QueryIntent [/Table/12/1/2022-05-17T14:15:36.541845Z/"\xa5\xd9(JW]Ny\xb1,\x1f\x95\x0e'\xf1g"/4/1,/Min), QueryIntent [/Table/12/1/2022-05-17T14:15:36.541845Z/"\xa5\xd9(JW]Ny\xb1,\x1f\x95\x0e'\xf1g"/5/1,/Min), [txn: b5a274fc]
           389.029ms      0.022ms                    event:kv/kvserver/replica_send.go:101 [n1,s1,r8/1:/Table/1{2-3}] read-only path
           389.051ms      0.022ms                    event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r8/1:/Table/1{2-3}] sequencing request
           389.066ms      0.015ms                    event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r8/1:/Table/1{2-3}] acquiring latches
           389.091ms      0.026ms                    event:kv/kvserver/replica_read.go:243 [n1,s1,r8/1:/Table/1{2-3}] executing read-only batch
           389.280ms      0.189ms                    event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371b\203\256\010\371 K\346\010\022\245\331(JW]Ny\261,\037\225\016'\361g\000\001\210" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           389.372ms      0.091ms                    event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371b\203\256\010\371 K\346\010\022\245\331(JW]Ny\261,\037\225\016'\361g\000\001\212\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:165279..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           389.468ms      0.096ms                    event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371b\203\256\010\371 K\346\010\022\245\331(JW]Ny\261,\037\225\016'\361g\000\001\213\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:165279..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           389.551ms      0.083ms                    event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371b\203\256\010\371 K\346\010\022\245\331(JW]Ny\261,\037\225\016'\361g\000\001\214\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:165279..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           389.638ms      0.087ms                    event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r8/1:/Table/1{2-3}] evaluated QueryIntent command header:<key:"\224\211\024\371b\203\256\010\371 K\346\010\022\245\331(JW]Ny\261,\037\225\016'\361g\000\001\215\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:165279..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           389.658ms      0.020ms                    event:kv/kvserver/replica_read.go:179 [n1,s1,r8/1:/Table/1{2-3}] read completed
           387.653ms      0.032ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] querying next range at /Table/15/1/762598315807571969/0
           387.704ms      0.051ms            event:kv/kvclient/kvcoord/dist_sender.go:1992 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] r11: sending batch 7 QueryIntent to (n1,s1):1
           387.731ms      0.027ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] sending request to local client
           387.737ms      0.006ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39
           387.756ms      0.019ms                event:server/node.go:915 [n1] node received request: 7 QueryIntent
           387.906ms      0.150ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing QueryIntent [/Table/15/1/762598315807571969/0,/Min), QueryIntent [/Table/15/1/762598315807571969/1/1,/Min), QueryIntent [/Table/15/1/762598315807571969/2/1,/Min), QueryIntent [/Table/15/2/"running"/2022-05-17T14:15:36.541845Z/762598315807571969/0,/Min), QueryIntent [/Table/15/3/NULL/NULL/762598315807571969/0,/Min), QueryIntent [/Table/15/4/"\xc0#{\x10y\x0fE^\xa5\x1b_ߕ\xa8\\\xb7"/"running"/2022-05-17T14:15:36.541845Z/762598315807571969/0,/Min), QueryIntent [/Table/15/4/"\xc0#{\x10y\x0fE^\xa5\x1b_ߕ\xa8\\\xb7"/"running"/2022-05-17T14:15:36.541845Z/762598315807571969/2/1,/Min), [txn: b5a274fc]
           387.929ms      0.022ms                event:kv/kvserver/replica_send.go:101 [n1,s1,r11/1:/Table/1{5-6}] read-only path
           387.959ms      0.030ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r11/1:/Table/1{5-6}] sequencing request
           387.977ms      0.018ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r11/1:/Table/1{5-6}] acquiring latches
           388.006ms      0.028ms                event:kv/kvserver/replica_read.go:243 [n1,s1,r11/1:/Table/1{5-6}] executing read-only batch
           388.149ms      0.144ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\225K \270\005\200\001\210" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936541845417 > priority:596780 sequence:10 > error_if_missi..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.242ms      0.092ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\225K \270\005\200\001\211\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936541845417 > priority:596780 sequence:11 > error_if_m..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.322ms      0.081ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\211\375\n\225K \270\005\200\001\212\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936541845417 > priority:596780 sequence:12 > error_if_m..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.406ms      0.084ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\212\022running\000\001\024\371b\203\256\010\371 K\346\010\375\n\225K \270\005\200\001\210" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:165279693654..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.493ms      0.087ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\n\225K \270\005\200\001\210" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936541845417 > priority:596780 sequence:14 > error_..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.584ms      0.091ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\300#{\020y\017E^\245\033_\337\225\250\\\267\000\001\022running\000\001\024\371b\203\256\010\371 K\346\010\375\n\225K \270\005\200\001\210" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:165..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.671ms      0.086ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r11/1:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\300#{\020y\017E^\245\033_\337\225\250\\\267\000\001\022running\000\001\024\371b\203\256\010\371 K\346\010\375\n\225K \270\005\200\001\212\211" > txn:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=0} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<> found_intent:true , err=<nil>
           388.694ms      0.023ms                event:kv/kvserver/replica_read.go:179 [n1,s1,r11/1:/Table/1{5-6}] read completed
           434.664ms     46.934ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] querying next range at /Table/SystemConfigSpan/Start
           434.716ms      0.052ms            event:kv/kvclient/kvcoord/dist_sender.go:1992 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] r6: sending batch 1 EndTxn to (n1,s1):1
           434.736ms      0.020ms            event:rpc/nodedialer/nodedialer.go:128 [n1,client=127.0.0.1:32862,hostssl,user=root,txn=b5a274fc] sending request to local client
           434.746ms      0.010ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:1 span.kind:server txnID:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39
           434.763ms      0.017ms                event:server/node.go:915 [n1] node received request: 1 EndTxn
           434.803ms      0.040ms                event:kv/kvserver/store_send.go:157 [n1,s1] executing EndTxn(commit modified-span (system-config)) [/Table/SystemConfigSpan/Start], [txn: b5a274fc]
           434.826ms      0.023ms                event:kv/kvserver/replica_send.go:105 [n1,s1,r6/1:/Table/{SystemCon…-11}] read-write path
           434.861ms      0.035ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n1,s1,r6/1:/Table/{SystemCon…-11}] sequencing request
           434.879ms      0.018ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n1,s1,r6/1:/Table/{SystemCon…-11}] acquiring latches
           434.911ms      0.032ms                event:kv/kvserver/replica_write.go:144 [n1,s1,r6/1:/Table/{SystemCon…-11}] applied timestamp cache
           434.932ms      0.021ms                event:kv/kvserver/replica_write.go:436 [n1,s1,r6/1:/Table/{SystemCon…-11}] executing read-write batch
           435.460ms      0.528ms                event:kv/kvserver/replica_evaluate.go:529 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated EndTxn command header:<key:"\210" sequence:17 > commit:true deadline:<wall_time:1652797233966295849 > internal_commit_trigger:<modified_span_trigger:<system_config_span:true > > lock_spans:<key:"\213\211\275\212\211" > lock_spans:<key:"\224\211\024\371b\203\256\010\37..., txn="sql txn" meta={id=b5a274fc key=/Table/SystemConfigSpan/Start pri=0.02778973 epo=0 ts=1652796936.541845417,0 min=1652796936.541845417,0 seq=17} lock=true stat=PENDING rts=1652796936.541845417,0 wto=false gul=1652796937.041845417,0 : resp=header:<txn:<meta:<id:b5a274fc-60eb-426e-a1d4-7dfb9b0fab39 key:"\210" write_timestamp:<wall_time:1652796936541845417 > min_timestamp:<wall_time:1652796936541845417 > priority:596780 sequence:17 > name:"sql txn" status:COMMITTED last_heartbeat:<wall_time..., err=<nil>
           435.489ms      0.029ms                event:kv/kvserver/replica_raft.go:111 [n1,s1,r6/1:/Table/{SystemCon…-11}] evaluated request
           436.208ms    151.545ms    event:util/log/event_log.go:32 [n1,client=127.0.0.1:32862,hostssl,user=root] Structured entry: {"Timestamp":1652796936541845417,"EventType":"alter_table","Statement":"ALTER TABLE bench.public.alter_table DROP COLUMN a, DROP COLUMN b, DROP COLUMN c","Tag":"ALTER TABLE","User":"root","DescriptorID":53,"TableName":"bench.public.alter_table","MutationID":1}
           436.247ms      0.040ms    event:sql/catalog/descs/leased_descriptors.go:234 [n1,client=127.0.0.1:32862,hostssl,user=root] releasing 0 descriptors
           436.272ms      0.025ms    event:sql/conn_executor_exec.go:1842 [n1,client=127.0.0.1:32862,hostssl,user=root] AutoCommit. err: <nil>

        (above trace from test AlterTableDropColumn/alter_table_drop_3_columns. got 23, expected 22)
        --- FAIL: TestBenchmarkExpectation/AlterTableDropColumn/alter_table_drop_3_columns (8.96s)
=== RUN   TestBenchmarkExpectation/AlterTableDropColumn
    --- FAIL: TestBenchmarkExpectation/AlterTableDropColumn (13.21s)
Reproduce

To reproduce, try: ```bash 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!

Jira issue: CRDB-15215

ajwerner commented 2 years ago

This needs the leniency backported. This is likely very rare. Closing until it pops back up.