ccl/benchccl/rttanalysisccl: TestBenchmarkExpectation failed

[cockroach-teamcity]

ccl/benchccl/rttanalysisccl.TestBenchmarkExpectation failed with artifacts on master @ 7e885e1d0f7d01b161c1fa9e0804aba53630e4f7:

          1203.843ms      0.091ms                event:kv/kvserver/replica_evaluate.go:508 [n4,s4,r11/2:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\213\000\000\375\t\371\363\223t*\200\001\210" > txn:<id:dcd144a4-cb39-4f16-8be3-32782dec9734 key:"\210" write_timestamp:<wall_time:1639453160195327639 > min_timestamp:<wall_time:1639453160195327639 > priority:788765 sequence:5 > error_i..., txn="sql txn" meta={id=dcd144a4 key=/Table/SystemConfigSpan/Start pri=0.03672973 epo=0 ts=1639453160.195327639,0 min=1639453160.195327639,0 seq=0} lock=true stat=PENDING rts=1639453160.195327639,0 wto=false gul=1639453160.695327639,0 : resp=header:<> found_intent:true , err=<nil>
          1203.885ms      0.042ms                event:scan stats: stepped 2 times (2 internal); seeked 2 times (2 internal)
          1203.981ms      0.096ms                event:kv/kvserver/replica_evaluate.go:508 [n4,s4,r11/2:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\231\222\001&\275>K\364\254\220\016\356\276\317A\266\000\001\022running\000\001\024\371a\270\021\350\371\013\244x\000\375\t\371\363\223t*\200\001\210" > txn:<id:dcd144a4-cb39-4f16-8be3-32782dec9734 key:"\210" write_timestamp:<wa..., txn="sql txn" meta={id=dcd144a4 key=/Table/SystemConfigSpan/Start pri=0.03672973 epo=0 ts=1639453160.195327639,0 min=1639453160.195327639,0 seq=0} lock=true stat=PENDING rts=1639453160.195327639,0 wto=false gul=1639453160.695327639,0 : resp=header:<> found_intent:true , err=<nil>
          1204.014ms      0.032ms                event:scan stats: stepped 2 times (2 internal); seeked 2 times (2 internal)
          1204.112ms      0.098ms                event:kv/kvserver/replica_evaluate.go:508 [n4,s4,r11/2:/Table/1{5-6}] evaluated QueryIntent command header:<key:"\227\214\022\231\222\001&\275>K\364\254\220\016\356\276\317A\266\000\001\022running\000\001\024\371a\270\021\350\371\013\244x\000\375\t\371\363\223t*\200\001\212\211" > txn:<id:dcd144a4-cb39-4f16-8be3-32782dec9734 key:"\210" write_timestamp..., txn="sql txn" meta={id=dcd144a4 key=/Table/SystemConfigSpan/Start pri=0.03672973 epo=0 ts=1639453160.195327639,0 min=1639453160.195327639,0 seq=0} lock=true stat=PENDING rts=1639453160.195327639,0 wto=false gul=1639453160.695327639,0 : resp=header:<> found_intent:true , err=<nil>
          1204.141ms      0.029ms                event:kv/kvserver/replica_read.go:178 [n4,s4,r11/2:/Table/1{5-6}] read completed
          1177.712ms    -26.428ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0"}
          1177.773ms      0.061ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1178.074ms      0.300ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1178.226ms      0.152ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1203.546ms     25.320ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1203.729ms      0.183ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1203.872ms      0.143ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1204.002ms      0.130ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"2","numInternalSteps":"2"}
          1257.474ms     84.646ms            event:kv/kvclient/kvcoord/range_iter.go:175 [n1,client=127.0.0.1:34000,hostssl,user=root,txn=dcd144a4] querying next range at /Table/SystemConfigSpan/Start
          1257.543ms      0.069ms            event:kv/kvclient/kvcoord/dist_sender.go:1934 [n1,client=127.0.0.1:34000,hostssl,user=root,txn=dcd144a4] r6: sending batch 1 EndTxn to (n2,s2):2
          1257.560ms      0.017ms            event:rpc/nodedialer/nodedialer.go:170 [n1,client=127.0.0.1:34000,hostssl,user=root,txn=dcd144a4] sending request to 127.0.0.1:43515
          1257.571ms      0.011ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 client:127.0.0.1:34000 hostssl: node:1 span.kind:client txn:dcd144a4 user:root
          1257.818ms      0.247ms                === operation:/cockroach.roachpb.Internal/Batch _verbose:1 node:2 span.kind:server
          1257.844ms      0.025ms                event:server/node.go:950 [n2] node received request: 1 EndTxn
          1257.891ms      0.048ms                event:kv/kvserver/store_send.go:157 [n2,s2] executing EndTxn(commit modified-span (system-config)) [/Table/SystemConfigSpan/Start], [txn: dcd144a4]
          1257.917ms      0.026ms                event:kv/kvserver/replica_send.go:157 [n2,s2,r6/2:/Table/{SystemCon…-11}] read-write path
          1257.952ms      0.035ms                event:kv/kvserver/concurrency/concurrency_manager.go:187 [n2,s2,r6/2:/Table/{SystemCon…-11}] sequencing request
          1257.967ms      0.015ms                event:kv/kvserver/concurrency/concurrency_manager.go:259 [n2,s2,r6/2:/Table/{SystemCon…-11}] acquiring latches
          1258.020ms      0.053ms                event:kv/kvserver/replica_write.go:143 [n2,s2,r6/2:/Table/{SystemCon…-11}] applied timestamp cache
          1258.037ms      0.017ms                event:kv/kvserver/replica_write.go:446 [n2,s2,r6/2:/Table/{SystemCon…-11}] executing read-write batch
          1258.160ms      0.123ms                event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal)
          1258.195ms      0.035ms                event:scan stats: stepped 0 times (0 internal); seeked 1 times (1 internal)
          1258.849ms      0.654ms                event:kv/kvserver/replica_evaluate.go:508 [n2,s2,r6/2:/Table/{SystemCon…-11}] evaluated EndTxn command header:<key:"\210" sequence:25 > commit:true deadline:<wall_time:1639453413575382873 > internal_commit_trigger:<modified_span_trigger:<system_config_span:true > > lock_spans:<key:"\213\211\310\212\211" > lock_spans:<key:"\213\211\312\212\211" > lock_spa..., txn="sql txn" meta={id=dcd144a4 key=/Table/SystemConfigSpan/Start pri=0.03672973 epo=0 ts=1639453160.195327639,0 min=1639453160.195327639,0 seq=25} lock=true stat=PENDING rts=1639453160.195327639,0 wto=false gul=1639453160.695327639,0 : resp=header:<txn:<meta:<id:dcd144a4-cb39-4f16-8be3-32782dec9734 key:"\210" write_timestamp:<wall_time:1639453160195327639 > min_timestamp:<wall_time:1639453160195327639 > priority:788765 sequence:25 > name:"sql txn" status:COMMITTED last_heartbeat:<wall_time..., err=<nil>
          1258.878ms      0.029ms                event:kv/kvserver/replica_proposal.go:833 [n2,s2,r6/2:/Table/{SystemCon…-11}] need consensus on write batch with op count=6
          1258.911ms      0.033ms                event:kv/kvserver/replica_raft.go:91 [n2,s2,r6/2:/Table/{SystemCon…-11}] evaluated request
          1258.928ms      0.017ms                event:kv/kvserver/replica_raft.go:135 [n2,s2,r6/2:/Table/{SystemCon…-11}] proposing command to write 0 new keys, 0 new values, -5 new intents, write batch size=955 bytes
          1258.142ms     -0.786ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0"}
          1258.182ms      0.039ms                structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"1","numInternalSeeks":"1","numInterfaceSteps":"0","numInternalSteps":"0"}
          1265.562ms      7.380ms                    === operation:raft application _verbose:1 node:2 range:6/2:/Table/{SystemCon…-11} store:2
          1265.635ms      0.074ms                    event:kv/kvserver/replica_application_state_machine.go:491 [n2,s2,r6/2:/Table/{SystemCon…-11}] applying command
          1265.728ms      0.092ms                    event:kv/kvserver/replica_application_state_machine.go:1117 [n2,s2,r6/2:/Table/{SystemCon…-11}] LocalResult (reply: (err: <nil>), *roachpb.EndTxnResponse, #encountered intents: 0, #acquired locks: 0, #resolved locks: 5#updated txns: 1 #end txns: 0, GossipFirstRange:false MaybeGossipSystemConfig:true MaybeGossipSystemConfigIfHaveFailure:false MaybeAddToSplitQueue:false MaybeGossipNodeLiveness:<nil>
          1265.954ms      0.227ms                    event:scan stats: stepped 176 times (162 internal); seeked 2 times (2 internal)
          1279.393ms     13.438ms                    event:kv/kvserver/replica_evaluate.go:508 [n2,s2,r6/2:/Table/{SystemCon…-11}] evaluated Scan command header:<key:"\210" end_key:"\223" > , txn=<nil> : resp=header:<num_keys:66 num_bytes:29868 > rows:<key:"\213\211\211\212\211" value:<raw_bytes:"\223\374\221\016\003\0225\n\006system\020\001\032!\n\013\n\005admin\0200\030\000\n\n\n\004root\0200\030\000\022\004node\030\002\"\000(\001@\000J\000" timestamp:<wal..., err=<nil>
          1279.421ms      0.029ms                    event:kv/kvserver/replica_gossip.go:121 [n2,s2,r6/2:/Table/{SystemCon…-11}] gossiping system config
          1265.934ms    -13.488ms                    structured:{"@type":"type.googleapis.com/cockroach.roachpb.ScanStats","numInterfaceSeeks":"2","numInternalSeeks":"2","numInterfaceSteps":"176","numInternalSteps":"162"}
          1291.118ms    195.127ms    event:util/log/event_log.go:32 [n1,client=127.0.0.1:34000,hostssl,user=root] Structured entry: {"Timestamp":1639453160195327639,"EventType":"create_type","Statement":"ALTER DATABASE test PRIMARY REGION \"us-east1\"","Tag":"ALTER DATABASE PRIMARY REGION","User":"root","DescriptorID":66,"TypeName":"test.public.crdb_internal_region"}
          1291.188ms      0.070ms    event:util/log/event_log.go:32 [n1,client=127.0.0.1:34000,hostssl,user=root] Structured entry: {"Timestamp":1639453160195327639,"EventType":"alter_database_primary_region","Statement":"ALTER DATABASE test PRIMARY REGION \"us-east1\"","Tag":"ALTER DATABASE PRIMARY REGION","User":"root","DescriptorID":64,"DatabaseName":"test","PrimaryRegionName":"\"us-east1\""}
          1291.233ms      0.045ms    event:sql/catalog/descs/leased_descriptors.go:234 [n1,client=127.0.0.1:34000,hostssl,user=root] releasing 0 descriptors
          1291.261ms      0.028ms    event:sql/conn_executor_exec.go:1849 [n1,client=127.0.0.1:34000,hostssl,user=root] AutoCommit. err: <nil>
        
        (above trace from test AlterPrimaryRegion/alter_empty_database_set_initial_primary_region. got 25, expected 26)
        --- FAIL: TestBenchmarkExpectation/AlterPrimaryRegion/alter_empty_database_set_initial_primary_region (47.99s)
=== RUN   TestBenchmarkExpectation/AlterPrimaryRegion
    --- FAIL: TestBenchmarkExpectation/AlterPrimaryRegion (48.35s)

Help

See also: [How To Investigate a Go Test Failure \(internal\)](https://cockroachlabs.atlassian.net/l/c/HgfXfJgM)Parameters in this failure:

• GOFLAGS=-json

/cc @cockroachdb/sql-experience

This test on roachdash | Improve this report!