Skip to content

Instantly share code, notes, and snippets.

@irfansharif

irfansharif/scale-test.log Secret

Last active April 14, 2022 19:53
Show Gist options
  • Save irfansharif/4cfb0be4ea819de940f8ca8fba8beabb to your computer and use it in GitHub Desktop.
Save irfansharif/4cfb0be4ea819de940f8ca8fba8beabb to your computer and use it in GitHub Desktop.
Download ZIP
Raw
scale-test.log
$ bazel test pkg/spanconfig:all --test_env=GOTRACEBACK=all --test_timeout=1000 --test_filter=TestScalability --test_arg -test.v --test_arg -show-logs --test_sharding_strategy=disabled --test_output all
INFO: Invocation ID: de64720f-c206-43e3-884c-d37a659ebb96
INFO: Analyzed 2 targets (0 packages loaded, 0 targets configured).
INFO: Found 1 target and 1 test target...
INFO: Elapsed time: 0.371s, Critical Path: 0.17s
INFO: 1 process: 1 internal.
INFO: Build completed successfully, 1 total action
PASSED: //pkg/spanconfig:spanconfig_test (see /private/var/tmp/_bazel_irfansharif/99e666e4e674209ecdb66b46371278df/execroot/cockroach/bazel-out/darwin_arm64-fastbuild/testlogs/pkg/spanconfig/spanconfig_test/test.log)
INFO: From Testing //pkg/spanconfig:spanconfig_test
==================== Test output for //pkg/spanconfig:spanconfig_test:
initialized metamorphic constant "span-reuse-rate" with value 100
initialized metamorphic constant "kv.rangefeed.use_dedicated_connection_class.enabled" with value true
initialized metamorphic constant "coldata-batch-size" with value 2515
initialized metamorphic constant "row-container-rows-per-chunk-shift" with value 1
initialized metamorphic constant "kv-batch-size" with value 1
initialized metamorphic constant "inverted-joiner-batch-size" with value 1
initialized metamorphic constant "zig-zag-joiner-batch-size" with value 1
initialized metamorphic constant "spilling-queue-initial-len" with value 14
initialized metamorphic constant "merge-joiner-groups-buffer" with value 6
initialized metamorphic constant "max-batch-size" with value 492
initialized metamorphic constant "max-batch-byte-size" with value 14534090
initialized metamorphic constant "resolve-membership-single-scan-enabled" with value false
initialized metamorphic constant "async-IE-result-channel-buffer-size" with value 18
initialized metamorphic constant "addsst-rewrite-concurrency" with value 6
initialized metamorphic constant "addsst-rewrite-forced" with value true
initialized metamorphic constant "split-scans-right-for-stats-first" with value true
initialized metamorphic constant "kv.rangefeed.catchup_scan_iterator_optimization.enabled" with value false
=== RUN TestScalability
test_log_scope.go:76: test logs captured to: /private/var/tmp/_bazel_irfansharif/99e666e4e674209ecdb66b46371278df/execroot/cockroach/_tmp/fa248f68a1dae30d2fdc90c344ba6286/logTestScalability1322546241
I220414 19:40:06.573088 25 server/config.go:654 [n?] 1 1 storage engine initialized
I220414 19:40:06.573304 25 server/config.go:657 [n?] 2 Pebble cache size: 128 MiB
I220414 19:40:06.573320 25 server/config.go:657 [n?] 3 store 0: in-memory, size 512 MiB
I220414 19:40:06.574864 25 1@rpc/pkg/rpc/tls.go:267 [n?] 4 server certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
I220414 19:40:06.574901 25 1@rpc/pkg/rpc/tls.go:316 [n?] 5 web UI certificate addresses: IP=127.0.0.1,::1; DNS=localhost,*.local; CN=node
W220414 19:40:06.575070 25 server/status/runtime.go:325 [n?] 6 could not parse build timestamp: parsing time "" as "2006/01/02 15:04:05": cannot parse "" as "2006"
I220414 19:40:06.600060 25 1@server/clock_monotonicity.go:65 [n?] 7 monitoring forward clock jumps based on server.clock.forward_jump_check_enabled
I220414 19:40:06.604020 25 server/init.go:197 [n?] 8 no stores initialized
I220414 19:40:06.604063 25 server/init.go:198 [n?] 9 awaiting `cockroach init` or join with an already initialized node
I220414 19:40:06.604078 25 server/init.go:262 [n?] 10 cluster 0f232cdb-3a95-4e0f-925d-787363b13e5f has been created
I220414 19:40:06.604096 25 server/init.go:263 [n?] 11 allocated node ID: n1 (for self)
I220414 19:40:06.604109 25 server/init.go:264 [n?] 12 active cluster version: 21.2-112
I220414 19:40:06.604222 174 1@server/server.go:1277 [n1] 13 connecting to gossip network to verify cluster ID "0f232cdb-3a95-4e0f-925d-787363b13e5f"
W220414 19:40:06.604225 25 1@gossip/pkg/gossip/gossip.go:1494 [n1] 14 no addresses found; use --join to specify a connected node
I220414 19:40:06.604335 25 gossip/pkg/gossip/gossip.go:401 [n1] 15 NodeDescriptor set to node_id:1 address:<network_field:"tcp" address_field:"127.0.0.1:49990" > attrs:<> locality:<tiers:<key:"region" value:"test" > tiers:<key:"dc" value:"dc1" > > ServerVersion:<major_val:21 minor_val:2 patch:0 internal:112 > build_tag:"unknown" started_at:1649965206604300000 cluster_name:"" sql_address:<network_field:"tcp" address_field:"127.0.0.1:49992" > http_address:<network_field:"tcp" address_field:"127.0.0.1:49991" >
I220414 19:40:06.606833 25 server/node.go:469 [n1] 16 initialized store s1
I220414 19:40:06.606864 25 kv/kvserver/pkg/kv/kvserver/stores.go:250 [n1] 17 read 0 node addresses from persistent storage
I220414 19:40:06.606883 174 1@server/server.go:1280 [n1] 18 node connected via gossip
I220414 19:40:06.607055 25 server/node.go:548 [n1] 19 started with engine type 2
I220414 19:40:06.607088 25 server/node.go:550 [n1] 20 started with attributes []
I220414 19:40:06.607218 25 1@server/server.go:1416 [n1] 21 starting https server at 127.0.0.1:49991 (use: 127.0.0.1:49991)
I220414 19:40:06.607278 25 1@server/server.go:1421 [n1] 22 starting postgres server at 127.0.0.1:49992 (use: 127.0.0.1:49992)
I220414 19:40:06.607296 25 1@server/server.go:1423 [n1] 23 starting grpc server at 127.0.0.1:49990
I220414 19:40:06.607349 25 1@server/server.go:1424 [n1] 24 advertising CockroachDB node at 127.0.0.1:49990
W220414 19:40:06.648016 42 kv/range_lookup.go:243 [n1,rangefeed=table-stats-cache,range-lookup=/Meta2/Table/20/NULL] 25 range lookup of key /Meta2/Table/20/NULL found only non-matching ranges []; retrying
W220414 19:40:06.649575 41 kv/range_lookup.go:243 [n1,rangefeed=table-stats-cache,range-lookup=/Table/20] 26 range lookup of key /Table/20 found only non-matching ranges []; retrying
I220414 19:40:06.696948 149 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:697 [n1,rangefeed=table-stats-cache,s1,r16/1:/Table/2{0-1}] 27 RangeFeed closed timestamp is empty
I220414 19:40:06.761785 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 28 spanconfig-subscriber: established range feed cache
I220414 19:40:06.762188 25 1@util/log/event_log.go:32 [n1] 29 ={"Timestamp":1649965206762186000,"EventType":"node_join","NodeID":1,"StartedAt":1649965206604300000,"LastUp":1649965206604300000}
I220414 19:40:06.762260 25 sql/sqlliveness/slinstance/slinstance.go:300 [n1] 30 starting SQL liveness instance
I220414 19:40:06.762783 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 31 spanconfig-subscriber: completed initial scan; flushed 0 events
I220414 19:40:06.762968 379 sql/sqlliveness/slstorage/slstorage.go:406 [n1] 32 inserted sqlliveness session 1bc2e4ab05414a0a9cdd92d6c10a4b04
I220414 19:40:06.762996 379 sql/sqlliveness/slinstance/slinstance.go:187 [n1] 33 created new SQL liveness session 1bc2e4ab05414a0a9cdd92d6c10a4b04
I220414 19:40:06.762974 448 sql/temporary_schema.go:515 [n1] 34 running temporary object cleanup background job
I220414 19:40:06.763015 498 sql/sqlstats/persistedsqlstats/pkg/sql/sqlstats/persistedsqlstats/provider.go:124 [n1] 35 starting sql-stats-worker with initial delay: 9m59.889388875s
I220414 19:40:06.763273 448 sql/temporary_schema.go:560 [n1] 36 found 0 temporary schemas
I220414 19:40:06.763291 448 sql/temporary_schema.go:563 [n1] 37 early exiting temporary schema cleaner as no temporary schemas were found
I220414 19:40:06.763303 448 sql/temporary_schema.go:564 [n1] 38 completed temporary object cleanup job
I220414 19:40:06.763313 448 sql/temporary_schema.go:647 [n1] 39 temporary object cleaner next scheduled to run at 2022-04-14 20:10:06.762927 +0000 UTC
I220414 19:40:06.767092 541 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 40 settings-watcher: established range feed cache
I220414 19:40:06.767272 541 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 41 settings-watcher: completed initial scan; flushed 0 events
I220414 19:40:06.767346 543 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 42 system-config-cache: established range feed cache
I220414 19:40:06.767506 543 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 43 system-config-cache: completed initial scan; flushed 46 events
I220414 19:40:06.771680 540 spanconfig/spanconfigmanager/manager.go:147 [n1] 44 started auto span config reconciliation job
I220414 19:40:06.771739 548 jobs/adopt.go:240 [n1] 45 job 753319302814400513: resuming execution
I220414 19:40:06.774615 551 jobs/registry.go:1134 [n1] 46 AUTO SPAN CONFIG RECONCILIATION job 753319302814400513: stepping through state running with error: <nil>
I220414 19:40:06.775955 551 jobs/registry.go:1351 [n1] 47 AUTO SPAN CONFIG RECONCILIATION job 753319302814400513: toggling idleness to true
I220414 19:40:06.791296 551 spanconfig/spanconfigreconciler/reconciler.go:244 [n1,job=753319302814400513] 48 fully reconciled: upserted len(48) entries, deleted len(0)
I220414 19:40:06.792463 551 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:263 [n1,job=753319302814400513] 49 established range feed over system.descriptors starting at time 1649965206.778928000,0
I220414 19:40:06.792518 551 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:316 [n1,job=753319302814400513] 50 established range feed over system.zones starting at time 1649965206.778928000,0
I220414 19:40:06.792542 551 spanconfig/spanconfigsqlwatcher/sqlwatcher.go:411 [n1,job=753319302814400513] 51 established range feed over system.protected_ts_records starting at time 1649965206.778928000,0
I220414 19:40:06.840657 546 util/log/event_log.go:32 [n1,intExec=optInToDiagnosticsStatReporting] 52 ={"Timestamp":1649965206767998000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"diagnostics.reporting.enabled\" = true","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-optInToDiagnosticsStatReporting","SettingName":"diagnostics.reporting.enabled","Value":"true"}
I220414 19:40:06.842488 686 migration/migrationmanager/manager.go:110 [n1,intExec=set-setting,migration-mgr] 53 no need to migrate, cluster already at newest version
I220414 19:40:06.843021 686 util/log/event_log.go:32 [n1,intExec=set-setting] 54 ={"Timestamp":1649965206842010000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING version = $1","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-set-setting","PlaceholderValues":["'21.2-112'"],"SettingName":"version","Value":"21.2-112"}
I220414 19:40:06.847631 709 util/log/event_log.go:32 [n1,intExec=initializeClusterSecret] 55 ={"Timestamp":1649965206846557000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"cluster.secret\" = gen_random_uuid()::STRING","Tag":"SET CLUSTER SETTING","User":"root","ApplicationName":"$ internal-initializeClusterSecret","SettingName":"cluster.secret","Value":"2eada3d2-e6bd-47dc-aa6b-ac9ac4170156"}
I220414 19:40:06.849588 724 5@util/log/event_log.go:32 [n1,intExec=create-default-DB] 56 ={"Timestamp":1649965206848196000,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS defaultdb","Tag":"CREATE DATABASE","User":"root","DescriptorID":100,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"defaultdb"}
I220414 19:40:06.850760 694 5@util/log/event_log.go:32 [n1,intExec=create-default-DB] 57 ={"Timestamp":1649965206849687000,"EventType":"create_database","Statement":"CREATE DATABASE IF NOT EXISTS postgres","Tag":"CREATE DATABASE","User":"root","DescriptorID":102,"ApplicationName":"$ internal-create-default-DB","DatabaseName":"postgres"}
I220414 19:40:06.855486 25 server/server_sql.go:1269 [n1] 58 done ensuring all necessary startup migrations have run
I220414 19:40:06.855592 761 jobs/job_scheduler.go:432 [n1] 59 waiting 4m0s before scheduled jobs daemon start
I220414 19:40:06.855629 765 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 60 tenant-settings-watcher: established range feed cache
I220414 19:40:06.855857 765 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 61 tenant-settings-watcher: completed initial scan; flushed 0 events
I220414 19:40:06.856566 764 server/auto_upgrade.go:59 [n1] 62 no need to upgrade, cluster already at the newest version
I220414 19:40:06.863822 25 1@server/server_sql.go:1339 [n1] 63 serving sql connections
I220414 19:40:06.870455 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 64 ={"Timestamp":1649965206869100000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.range_merge.queue_enabled\" = false","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.range_merge.queue_enabled","Value":"false"}
I220414 19:40:06.876434 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 65 ={"Timestamp":1649965206875446000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"server.eventlog.enabled\" = 'false'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"server.eventlog.enabled","Value":"false"}
I220414 19:40:06.876886 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 66 ={"Timestamp":1649965206876621000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.closed_timestamp.target_duration\" = '100ms'","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"kv.closed_timestamp.target_duration","Value":"00:00:00.1"}
I220414 19:40:06.877598 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 67 ={"Timestamp":1649965206877333000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.stats.automatic_collection.enabled\" = false","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.stats.automatic_collection.enabled","Value":"false"}
I220414 19:40:06.878258 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 68 ={"Timestamp":1649965206878014000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.stats.flush.enabled\" = false","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.stats.flush.enabled","Value":"false"}
I220414 19:40:06.878849 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 69 ={"Timestamp":1649965206878612000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"sql.metrics.statement_details.enabled\" = false","Tag":"SET CLUSTER SETTING","User":"root","SettingName":"sql.metrics.statement_details.enabled","Value":"false"}
I220414 19:40:06.879594 653 util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 70 ={"Timestamp":1649965206879350000,"EventType":"set_cluster_setting","Statement":"SET CLUSTER SETTING \"kv.transaction.max_intents_bytes\" = $1","Tag":"SET CLUSTER SETTING","User":"root","PlaceholderValues":["12582912"],"SettingName":"kv.transaction.max_intents_bytes","Value":"12582912"}
I220414 19:40:06.880797 653 5@util/log/event_log.go:32 [n1,client=127.0.0.1:49993,user=root] 71 ={"Timestamp":1649965206880003000,"EventType":"create_database","Statement":"CREATE DATABASE db","Tag":"CREATE DATABASE","User":"root","DescriptorID":104,"DatabaseName":"db"}
I220414 19:40:07.207173 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 72 sqlwatcher received 6 updates
I220414 19:40:07.564694 22 util/admission/granter.go:941 [n1] 73 CPULoad switching to period 250ms
I220414 19:40:08.260910 55 1@gossip/pkg/gossip/gossip.go:1510 [n1] 74 node has connected to cluster via gossip
I220414 19:40:08.260992 55 kv/kvserver/pkg/kv/kvserver/stores.go:269 [n1] 75 wrote 0 node addresses to persistent storage
W220414 19:40:16.609563 284 1@server/status/runtime.go:468 [n1] 76 unable to get file descriptor usage (will not try again): not implemented on darwin
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 +__level_____count____size___score______in__ingest(sz_cnt)____move(sz_cnt)___write(sz_cnt)____read___r-amp___w-amp
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + WAL 1 43 M - 203 M - - - - 208 M - - - 1.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 0 0 0 B 0.00 165 M 0 B 0 0 B 0 35 M 18 0 B 0 0.2
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 1 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 2 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 3 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 4 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 5 0 0 B 0.00 0 B 0 B 0 0 B 0 0 B 0 0 B 0 0.0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + 6 7 24 M - 35 M 0 B 0 0 B 0 66 M 19 77 M 1 1.9
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + total 7 24 M - 208 M 0 B 0 0 B 0 309 M 37 77 M 1 1.5
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + flush 3
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 +compact 6 0 B 0 B 0 (size == estimated-debt, score = in-progress-bytes, in = num-in-progress)
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + ctype 6 0 0 0 0 0 (default, delete, elision, move, read, rewrite)
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + memtbl 1 64 M
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 +zmemtbl 0 0 B
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + ztbl 0 0 B
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + bcache 1.1 K 33 M 97.8% (score == hit-rate)
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + tcache 6 4.0 K 100.0% (score == hit-rate)
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + snaps 0 - 0 (score == earliest seq num)
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + titers 0
I220414 19:40:26.610043 279 kv/kvserver/pkg/kv/kvserver/store.go:3263 [n1,s1] 77 + filter - - 83.9% (score == utility)
I220414 19:40:30.657516 101044 kv/kvserver/pkg/kv/kvserver/replica_consistency.go:267 [n1,consistencyChecker,s1,r4/1:/System{/tsd-tse}] 78 triggering stats recomputation to resolve delta of {ContainsEstimates:7644 LastUpdateNanos:1649965226867428000 IntentAge:0 GCBytesAge:0 LiveBytes:-24541 LiveCount:-1274 KeyBytes:-67857 KeyCount:-1274 ValBytes:43316 ValCount:-1274 IntentBytes:0 IntentCount:0 SeparatedIntentCount:0 SysBytes:0 SysCount:0 AbortSpanBytes:0}
I220414 19:40:33.329324 22 util/admission/granter.go:941 [n1] 79 CPULoad switching to period 1ms
I220414 19:40:33.333954 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 80 finished epoch=0 (took 26.451988s); running total: 100000 tables in 26.451988s
I220414 19:40:34.313598 231 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 81 RangeFeed closed timestamp 1649965233.346766000,0 is behind by 966.828ms
I220414 19:40:34.356279 231 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 82 handle raft ready: 0.9s [applied=131, batches=3, state_assertions=0]; node might be overloaded
I220414 19:40:35.329364 22 util/admission/granter.go:941 [n1] 83 CPULoad switching to period 250ms
I220414 19:40:35.475414 231 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 84 handle raft ready: 1.0s [applied=188, batches=1, state_assertions=0]; node might be overloaded
I220414 19:40:36.100173 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 85 sqltranslator translated 0 records in 28.892895s
I220414 19:40:36.468673 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 86 sqlwatcher received 100000 updates
W220414 19:40:51.902308 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 87 latency jump (prev avg 1.16ms, current 2.37ms)
I220414 19:41:00.635722 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 88 local QPS 17745.30 is below max threshold 19519.83 (mean=17745.30); no rebalancing needed
I220414 19:41:04.151885 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 89 finished epoch=1 (took 30.81778s); running total: 200000 tables in 57.26992s
I220414 19:41:04.533453 277 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11}] 90 RangeFeed closed timestamp 1649965263.966529000,0 is behind by 566.922ms
I220414 19:41:04.829300 22 util/admission/granter.go:941 [n1] 91 CPULoad switching to period 1ms
I220414 19:41:05.829396 22 util/admission/granter.go:941 [n1] 92 CPULoad switching to period 250ms
I220414 19:41:06.389330 229 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 93 handle raft ready: 1.5s [applied=194, batches=1, state_assertions=0]; node might be overloaded
I220414 19:41:25.401317 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 94 sqltranslator translated 100000 records in 48.932576s
I220414 19:41:28.504736 551 spanconfig/spanconfigreconciler/reconciler.go:487 [n1,job=753319302814400513] 95 incrementally reconciled: +100000 -0 entries in 3.103309s
W220414 19:41:28.632682 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:201 [n1] 96 spanconfig-subscriber: failed with rangefeed buffer limit exceeded, retrying...
I220414 19:41:28.692836 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 97 spanconfig-subscriber: established range feed cache
I220414 19:41:29.251784 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 98 sqlwatcher received 100000 updates
I220414 19:41:29.790269 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 99 spanconfig-subscriber: completed initial scan; flushed 100048 events
I220414 19:41:34.291031 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 100 finished epoch=2 (took 30.139075s); running total: 300000 tables in 1m27.409066s
I220414 19:41:34.667774 217 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 101 RangeFeed closed timestamp 1649965294.004296000,0 is behind by 663.476ms
I220414 19:41:34.734048 217 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 102 handle raft ready: 0.6s [applied=130, batches=3, state_assertions=0]; node might be overloaded
I220414 19:41:35.079348 22 util/admission/granter.go:941 [n1] 103 CPULoad switching to period 1ms
I220414 19:41:36.184504 217 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 104 handle raft ready: 1.4s [applied=157, batches=1, state_assertions=0]; node might be overloaded
I220414 19:41:37.081631 22 util/admission/granter.go:941 [n1] 105 CPULoad switching to period 250ms
W220414 19:42:00.966530 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 106 latency jump (prev avg 1.27ms, current 2.86ms)
I220414 19:42:03.261744 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 107 finished epoch=3 (took 28.97064s); running total: 400000 tables in 1m56.379781s
I220414 19:42:03.822479 244 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 108 RangeFeed closed timestamp 1649965323.134724000,0 is behind by 687.751ms
I220414 19:42:03.889600 244 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 109 handle raft ready: 0.7s [applied=142, batches=3, state_assertions=0]; node might be overloaded
I220414 19:42:04.081580 22 util/admission/granter.go:941 [n1] 110 CPULoad switching to period 1ms
I220414 19:42:04.876676 244 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 111 handle raft ready: 0.9s [applied=193, batches=1, state_assertions=0]; node might be overloaded
I220414 19:42:06.082609 22 util/admission/granter.go:941 [n1] 112 CPULoad switching to period 250ms
I220414 19:42:07.728079 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 113 local QPS 21112.64 is below max threshold 23223.90 (mean=21112.64); no rebalancing needed
I220414 19:42:15.608217 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 114 sqltranslator translated 100000 records in 46.356368s
I220414 19:42:18.681697 551 spanconfig/spanconfigreconciler/reconciler.go:487 [n1,job=753319302814400513] 115 incrementally reconciled: +100000 -0 entries in 3.07341s
W220414 19:42:18.792782 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:201 [n1] 116 spanconfig-subscriber: failed with rangefeed buffer limit exceeded, retrying...
I220414 19:42:18.891866 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 117 spanconfig-subscriber: established range feed cache
I220414 19:42:20.041115 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 118 sqlwatcher received 200000 updates
I220414 19:42:20.069966 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 119 spanconfig-subscriber: completed initial scan; flushed 200048 events
I220414 19:42:33.627004 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 120 finished epoch=4 (took 30.365189s); running total: 500000 tables in 2m26.74504s
I220414 19:42:34.271469 277 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11}] 121 RangeFeed closed timestamp 1649965353.627195999,0 is behind by 644.270001ms
I220414 19:42:35.775463 194 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 122 handle raft ready: 1.2s [applied=192, batches=1, state_assertions=0]; node might be overloaded
W220414 19:42:45.992133 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 123 latency jump (prev avg 0.76ms, current 5.17ms)
I220414 19:42:57.082081 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 124 local QPS 21112.64 is below max threshold 23223.90 (mean=21112.64); no rebalancing needed
I220414 19:43:03.752912 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 125 finished epoch=5 (took 30.125833s); running total: 600000 tables in 2m56.870947s
I220414 19:43:05.332575 22 util/admission/granter.go:941 [n1] 126 CPULoad switching to period 1ms
I220414 19:43:05.884103 194 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 127 RangeFeed closed timestamp 1649965383.753119999,0 is behind by 2.130981001s
I220414 19:43:05.893704 194 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 128 handle raft ready: 1.8s [applied=152, batches=1, state_assertions=0]; node might be overloaded
I220414 19:43:06.332708 22 util/admission/granter.go:941 [n1] 129 CPULoad switching to period 250ms
I220414 19:43:08.264029 194 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 130 handle raft ready: 2.0s [applied=155, batches=1, state_assertions=0]; node might be overloaded
W220414 19:43:31.033094 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 131 latency jump (prev avg 1.23ms, current 2.26ms)
I220414 19:43:38.836803 22 util/admission/granter.go:941 [n1] 132 CPULoad switching to period 1ms
I220414 19:43:39.837823 22 util/admission/granter.go:941 [n1] 133 CPULoad switching to period 250ms
I220414 19:43:42.087864 22 util/admission/granter.go:941 [n1] 134 CPULoad switching to period 1ms
I220414 19:43:43.059044 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 135 finished epoch=6 (took 39.306052s); running total: 700000 tables in 3m36.177081s
I220414 19:43:43.073765 220 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 136 RangeFeed closed timestamp 1649965421.414872000,0 is behind by 1.65889s
I220414 19:43:43.089899 220 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 137 handle raft ready: 1.6s [applied=99, batches=1, state_assertions=0]; node might be overloaded
I220414 19:43:45.326880 220 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 138 handle raft ready: 2.2s [applied=187, batches=2, state_assertions=0]; node might be overloaded
I220414 19:43:46.100870 22 util/admission/granter.go:941 [n1] 139 CPULoad switching to period 250ms
I220414 19:43:46.579653 220 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 140 handle raft ready: 0.7s [applied=64, batches=1, state_assertions=0]; node might be overloaded
I220414 19:43:54.524507 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 141 local QPS 20864.37 is below max threshold 22950.80 (mean=20864.37); no rebalancing needed
W220414 19:44:04.059535 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 142 latency jump (prev avg 0.91ms, current 1.82ms)
I220414 19:44:06.163368 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 143 sqltranslator translated 200000 records in 1m46.122173s
I220414 19:44:12.341914 551 spanconfig/spanconfigreconciler/reconciler.go:487 [n1,job=753319302814400513] 144 incrementally reconciled: +200000 -0 entries in 6.178454s
W220414 19:44:12.531384 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:201 [n1] 145 spanconfig-subscriber: failed with rangefeed buffer limit exceeded, retrying...
I220414 19:44:12.531552 264 kv/kvserver/rangefeed/budget.go:166 [n1,s1,r43/1:/Table/{47-50},raft] 146 trying to get allocation from already closed budget
I220414 19:44:12.708052 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 147 spanconfig-subscriber: established range feed cache
I220414 19:44:14.100895 22 util/admission/granter.go:941 [n1] 148 CPULoad switching to period 1ms
I220414 19:44:14.339386 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 149 sqlwatcher received 300000 updates
I220414 19:44:16.904133 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 150 spanconfig-subscriber: completed initial scan; flushed 400048 events
I220414 19:44:18.114299 22 util/admission/granter.go:941 [n1] 151 CPULoad switching to period 250ms
I220414 19:44:22.864569 22 util/admission/granter.go:941 [n1] 152 CPULoad switching to period 1ms
I220414 19:44:23.320910 63 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 153 RangeFeed closed timestamp 1649965461.989692000,0 is behind by 1.331213s
I220414 19:44:23.322463 63 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 154 handle raft ready: 1.2s [applied=15, batches=1, state_assertions=0]; node might be overloaded
I220414 19:44:25.366817 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 155 finished epoch=7 (took 42.307692s); running total: 800000 tables in 4m18.484853s
I220414 19:44:25.485244 63 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 156 handle raft ready: 2.2s [applied=186, batches=3, state_assertions=0]; node might be overloaded
I220414 19:44:27.221094 218 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 157 handle raft ready: 0.7s [applied=60, batches=1, state_assertions=0]; node might be overloaded
I220414 19:44:28.867558 22 util/admission/granter.go:941 [n1] 158 CPULoad switching to period 250ms
I220414 19:44:56.131028 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 159 local QPS 21468.42 is below max threshold 23615.26 (mean=21468.42); no rebalancing needed
I220414 19:45:00.867499 22 util/admission/granter.go:941 [n1] 160 CPULoad switching to period 1ms
I220414 19:45:01.132597 215 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 161 RangeFeed closed timestamp 1649965500.128312000,0 is behind by 1.004281s
I220414 19:45:01.134048 215 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 162 handle raft ready: 0.9s [applied=35, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:03.295365 215 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 163 handle raft ready: 2.2s [applied=71, batches=3, state_assertions=0]; node might be overloaded
I220414 19:45:04.623395 215 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 164 handle raft ready: 1.3s [applied=187, batches=2, state_assertions=0]; node might be overloaded
I220414 19:45:05.371089 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 165 finished epoch=8 (took 40.004198s); running total: 900000 tables in 4m58.489124s
I220414 19:45:05.579106 215 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 166 handle raft ready: 1.0s [applied=131, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:06.605110 27 util/admission/work_queue.go:475 [n1] 167 kv: FIFO threshold for tenant 1 is -128
I220414 19:45:06.705556 287 util/admission/work_queue.go:475 [-] 168 kv: FIFO threshold for tenant 1 is -128
I220414 19:45:06.869697 22 util/admission/granter.go:941 [n1] 169 CPULoad switching to period 250ms
I220414 19:45:07.543017 215 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 170 handle raft ready: 1.6s [applied=124, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:07.543680 277 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11}] 171 RangeFeed closed timestamp 1649965505.371309999,0 is behind by 2.172367001s
W220414 19:45:16.119202 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 172 latency jump (prev avg 0.89ms, current 1.39ms)
W220414 19:45:40.190726 804 2@rpc/pkg/rpc/clock_offset.go:216 [n1,rnode=1,raddr=127.0.0.1:49990,class=default,heartbeat] 173 latency jump (prev avg 0.84ms, current 15.30ms)
I220414 19:45:41.619621 22 util/admission/granter.go:941 [n1] 174 CPULoad switching to period 1ms
I220414 19:45:42.204437 253 kv/kvserver/pkg/kv/kvserver/replica_rangefeed.go:699 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 175 RangeFeed closed timestamp 1649965540.734039000,0 is behind by 1.470395s
I220414 19:45:42.206685 253 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 176 handle raft ready: 1.4s [applied=35, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:43.849005 253 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 177 handle raft ready: 1.6s [applied=172, batches=3, state_assertions=0]; node might be overloaded
I220414 19:45:44.728048 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:107 [-] 178 finished epoch=9 (took 39.356894s); running total: 1000000 tables in 5m37.846084s
I220414 19:45:45.065780 253 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 179 handle raft ready: 0.8s [applied=183, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:45.611800 253 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 180 handle raft ready: 0.5s [applied=177, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:46.621614 22 util/admission/granter.go:941 [n1] 181 CPULoad switching to period 250ms
I220414 19:45:46.907369 253 kv/kvserver/pkg/kv/kvserver/store_raft.go:515 [n1,s1,r6/1:/Table/{SystemCon…-11},raft] 182 handle raft ready: 1.3s [applied=96, batches=1, state_assertions=0]; node might be overloaded
I220414 19:45:47.847536 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 183 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:48.702553 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 184 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:49.632247 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 185 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:50.576967 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 186 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:51.372800 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 187 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:51.880188 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 188 local QPS 19658.19 is below max threshold 21624.01 (mean=19658.19); no rebalancing needed
I220414 19:45:52.181208 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 189 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:52.952092 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 190 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:53.714758 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 191 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:54.703500 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 192 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:55.421982 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 193 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:56.127022 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 194 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:56.967464 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 195 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:57.822414 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 196 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:58.930495 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 197 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:45:59.743182 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 198 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:00.557486 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 199 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:01.349255 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 200 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:02.109232 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 201 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:03.230631 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 202 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:03.944926 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 203 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:04.662704 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 204 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:05.393518 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 205 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:06.137987 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 206 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:07.374109 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 207 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:08.222551 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 208 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:08.250326 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 209 sqltranslator translated 300000 records in 1m53.910851s
I220414 19:46:09.110465 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 210 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:10.076910 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 211 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:11.239545 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 212 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:16.113606 551 spanconfig/spanconfigreconciler/reconciler.go:487 [n1,job=753319302814400513] 213 incrementally reconciled: +300000 -0 entries in 7.863214s
W220414 19:46:16.225461 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:201 [n1] 214 spanconfig-subscriber: failed with rangefeed buffer limit exceeded, retrying...
I220414 19:46:16.641413 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 215 spanconfig-subscriber: established range feed cache
I220414 19:46:16.871651 22 util/admission/granter.go:941 [n1] 216 CPULoad switching to period 1ms
I220414 19:46:19.236393 551 spanconfig/spanconfigreconciler/reconciler.go:405 [n1,job=753319302814400513] 217 sqlwatcher received 300000 updates
I220414 19:46:19.334310 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 218 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 400048
I220414 19:46:21.857409 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 219 spanconfig-subscriber: completed initial scan; flushed 700048 events
I220414 19:46:21.874639 22 util/admission/granter.go:941 [n1] 220 CPULoad switching to period 250ms
I220414 19:46:21.977226 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 221 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:24.371240 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 222 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:26.849367 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 223 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:29.393760 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 224 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:31.950414 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 225 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:34.586783 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 226 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:37.032251 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 227 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:39.745593 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 228 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:42.173138 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 229 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:44.949045 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 230 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:46.146580 278 kv/kvserver/pkg/kv/kvserver/store_rebalancer.go:291 [n1,s1,store-rebalancer] 231 local QPS 20899.32 is below max threshold 22989.25 (mean=20899.32); no rebalancing needed
I220414 19:46:47.504802 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 232 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:49.974212 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 233 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:52.692154 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 234 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:55.083289 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 235 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:46:57.761982 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 236 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:00.264687 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 237 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:02.718882 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 238 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:05.379323 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 239 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:07.959379 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 240 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:10.289037 551 spanconfig/spanconfigreconciler/reconciler.go:453 [n1,job=753319302814400513] 241 sqltranslator translated 300000 records in 51.052571s
I220414 19:47:10.471787 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 242 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:12.981397 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 243 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:18.256947 551 spanconfig/spanconfigreconciler/reconciler.go:487 [n1,job=753319302814400513] 244 incrementally reconciled: +300000 -0 entries in 7.96784s
W220414 19:47:18.544273 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:201 [n1] 245 spanconfig-subscriber: failed with rangefeed buffer limit exceeded, retrying...
I220414 19:47:19.094307 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:124 [-] 246 SucceedsSoon: expected kvaccessor to hold 1000048 records, found 700048
I220414 19:47:19.286002 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:316 [n1] 247 spanconfig-subscriber: established range feed cache
I220414 19:47:19.874582 22 util/admission/granter.go:941 [n1] 248 CPULoad switching to period 1ms
I220414 19:47:20.874592 22 util/admission/granter.go:941 [n1] 249 CPULoad switching to period 250ms
I220414 19:47:25.066720 375 kv/kvclient/rangefeed/rangefeedcache/watcher.go:357 [n1] 250 spanconfig-subscriber: completed initial scan; flushed 1000048 events
I220414 19:47:25.225036 25 spanconfig_test/pkg/spanconfig/spanconfig_test.go:145 [-] 251 end-to-end span config reconciliation (post-creation) for 1000048 tables took 1m40.496927s
I220414 19:47:25.225164 25 testutils/testcluster/testcluster.go:107 [-] 252 TestCluster quiescing nodes
W220414 19:47:25.225478 379 sql/sqlliveness/slinstance/slinstance.go:224 [n1] 253 exiting heartbeat loop
W220414 19:47:25.225516 537 jobs/registry.go:806 [n1] 254 canceling all adopted jobs due to stopper quiescing
I220414 19:47:25.226000 551 jobs/registry.go:1134 [n1] 255 AUTO SPAN CONFIG RECONCILIATION job 753319302814400513: stepping through state succeeded with error: <nil>
W220414 19:47:25.226132 551 kv/txn.go:728 [n1] 256 failure aborting transaction: node unavailable; try another peer; abort caused by: context canceled
spanconfig_test.go:147: -- test log scope end --
--- PASS: TestScalability (438.91s)
PASS
================================================================================
//pkg/spanconfig:spanconfig_test (cached) PASSED in 440.0s
Executed 0 out of 1 test: 1 test passes.
INFO: Build completed successfully, 1 total action
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment