[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:26.134397 22345 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.210.126:43473
I20260812 06:16:26.135624 22345 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:26.136322 22345 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:26.144825 22350 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:26.145705 22355 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:26.146901 22353 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:26.147429 22345 server_base.cc:1061] running on GCE node
I20260812 06:16:26.148082 22345 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:26.148192 22345 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:26.148231 22345 hybrid_clock.cc:648] HybridClock initialized: now 1786515386148229 us; error 0 us; skew 500 ppm
I20260812 06:16:26.150264 22345 webserver.cc:533] Webserver started at http://127.21.210.126:38131/ using document root <none> and password file <none>
I20260812 06:16:26.150893 22345 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:26.150964 22345 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:26.151175 22345 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:26.153674 22345 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/master-0-root/instance:
uuid: "5c7712edc6824e7fbc2205b3ddfd49ec"
format_stamp: "Formatted at 2026-08-12 06:16:26 on dist-test-slave-7kzw"
I20260812 06:16:26.158150 22345 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.007s	sys 0.000s
I20260812 06:16:26.161254 22371 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:26.162349 22345 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:26.162515 22345 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/master-0-root
uuid: "5c7712edc6824e7fbc2205b3ddfd49ec"
format_stamp: "Formatted at 2026-08-12 06:16:26 on dist-test-slave-7kzw"
I20260812 06:16:26.162631 22345 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:26.196925 22345 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:26.197650 22345 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:26.197861 22345 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:26.207262 22345 rpc_server.cc:307] RPC server started. Bound to: 127.21.210.126:43473
I20260812 06:16:26.207358 22461 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.210.126:43473 every 8 connection(s)
I20260812 06:16:26.209744 22463 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:26.216223 22463 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: Bootstrap starting.
I20260812 06:16:26.218901 22463 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:26.219961 22463 log.cc:826] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:26.221900 22463 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: No bootstrap required, opened a new log
I20260812 06:16:26.225286 22463 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER }
I20260812 06:16:26.225539 22463 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:26.225630 22463 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5c7712edc6824e7fbc2205b3ddfd49ec, State: Initialized, Role: FOLLOWER
I20260812 06:16:26.226423 22463 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER }
I20260812 06:16:26.226600 22463 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:26.226742 22463 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:26.226905 22463 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:26.227828 22463 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER }
I20260812 06:16:26.228358 22463 leader_election.cc:304] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 5c7712edc6824e7fbc2205b3ddfd49ec; no voters: 
I20260812 06:16:26.228785 22463 leader_election.cc:290] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:26.228964 22468 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:26.229259 22468 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 1 LEADER]: Becoming Leader. State: Replica: 5c7712edc6824e7fbc2205b3ddfd49ec, State: Running, Role: LEADER
I20260812 06:16:26.229806 22468 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER }
I20260812 06:16:26.229895 22463 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:26.231784 22473 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5c7712edc6824e7fbc2205b3ddfd49ec. Latest consensus state: current_term: 1 leader_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER } }
I20260812 06:16:26.231837 22470 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5c7712edc6824e7fbc2205b3ddfd49ec" member_type: VOTER } }
I20260812 06:16:26.231915 22473 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:26.231958 22470 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:26.232538 22483 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:26.232698 22345 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:26.235347 22483 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:26.240103 22483 catalog_manager.cc:1383] Generated new cluster ID: ec6731480e6644c99a4bf2481ad0707b
I20260812 06:16:26.240175 22483 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:26.269824 22483 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:26.271386 22483 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:26.286883 22483 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: Generated new TSK 0
I20260812 06:16:26.287685 22483 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:26.297725 22345 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:26.300559 22498 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:26.300715 22345 server_base.cc:1061] running on GCE node
W20260812 06:16:26.300535 22500 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:26.300875 22503 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:26.301101 22345 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:26.301146 22345 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:26.301162 22345 hybrid_clock.cc:648] HybridClock initialized: now 1786515386301162 us; error 0 us; skew 500 ppm
I20260812 06:16:26.302067 22345 webserver.cc:533] Webserver started at http://127.21.210.65:44801/ using document root <none> and password file <none>
I20260812 06:16:26.302253 22345 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:26.302309 22345 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:26.302404 22345 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:26.302848 22345 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/instance:
uuid: "3f4a7acb55504480ad16844fe7dfde3a"
format_stamp: "Formatted at 2026-08-12 06:16:26 on dist-test-slave-7kzw"
I20260812 06:16:26.304776 22345 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.001s	sys 0.001s
I20260812 06:16:26.305886 22512 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:26.306162 22345 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:26.306228 22345 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root
uuid: "3f4a7acb55504480ad16844fe7dfde3a"
format_stamp: "Formatted at 2026-08-12 06:16:26 on dist-test-slave-7kzw"
I20260812 06:16:26.306339 22345 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:26.330549 22345 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:26.331650 22345 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:26.332211 22345 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:26.333433 22345 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:26.333496 22345 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:26.333588 22345 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:26.333635 22345 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:26.341409 22345 rpc_server.cc:307] RPC server started. Bound to: 127.21.210.65:41791
I20260812 06:16:26.341444 22611 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.210.65:41791 every 8 connection(s)
I20260812 06:16:26.356184 22612 heartbeater.cc:344] Connected to a master server at 127.21.210.126:43473
I20260812 06:16:26.356496 22612 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:26.357064 22612 heartbeater.cc:507] Master 127.21.210.126:43473 requested a full tablet report, sending...
I20260812 06:16:26.358886 22396 ts_manager.cc:194] Registered new tserver with Master: 3f4a7acb55504480ad16844fe7dfde3a (127.21.210.65:41791)
I20260812 06:16:26.359241 22345 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017052696s
I20260812 06:16:26.360538 22396 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:52402
I20260812 06:16:26.371928 22396 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:52404:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:26.388547 22550 tablet_service.cc:1511] Processing CreateTablet for tablet 870d1b57c5084c2bac1706b1a8d07d18 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c34aba4d7a034df0b20334799ed29231]), partition=
I20260812 06:16:26.389057 22550 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 870d1b57c5084c2bac1706b1a8d07d18. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:26.392217 22629 tablet_bootstrap.cc:492] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Bootstrap starting.
I20260812 06:16:26.393514 22629 tablet_bootstrap.cc:654] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:26.395056 22629 tablet_bootstrap.cc:492] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: No bootstrap required, opened a new log
I20260812 06:16:26.395205 22629 ts_tablet_manager.cc:1403] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:26.395697 22629 raft_consensus.cc:359] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f4a7acb55504480ad16844fe7dfde3a" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 41791 } }
I20260812 06:16:26.395915 22629 raft_consensus.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:26.395994 22629 raft_consensus.cc:740] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f4a7acb55504480ad16844fe7dfde3a, State: Initialized, Role: FOLLOWER
I20260812 06:16:26.396173 22629 consensus_queue.cc:260] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f4a7acb55504480ad16844fe7dfde3a" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 41791 } }
I20260812 06:16:26.396294 22629 raft_consensus.cc:399] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:26.396350 22629 raft_consensus.cc:493] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:26.396409 22629 raft_consensus.cc:3060] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:26.397194 22629 raft_consensus.cc:515] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f4a7acb55504480ad16844fe7dfde3a" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 41791 } }
I20260812 06:16:26.397356 22629 leader_election.cc:304] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 3f4a7acb55504480ad16844fe7dfde3a; no voters: 
I20260812 06:16:26.397612 22629 leader_election.cc:290] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:26.397729 22631 raft_consensus.cc:2804] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:26.397913 22631 raft_consensus.cc:697] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 1 LEADER]: Becoming Leader. State: Replica: 3f4a7acb55504480ad16844fe7dfde3a, State: Running, Role: LEADER
I20260812 06:16:26.398191 22629 ts_tablet_manager.cc:1434] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:26.398097 22631 consensus_queue.cc:237] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f4a7acb55504480ad16844fe7dfde3a" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 41791 } }
I20260812 06:16:26.398793 22612 heartbeater.cc:499] Master 127.21.210.126:43473 was elected leader, sending a full tablet report...
I20260812 06:16:26.401242 22396 catalog_manager.cc:5719] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a reported cstate change: term changed from 0 to 1, leader changed from <none> to 3f4a7acb55504480ad16844fe7dfde3a (127.21.210.65). New cstate: current_term: 1 leader_uuid: "3f4a7acb55504480ad16844fe7dfde3a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f4a7acb55504480ad16844fe7dfde3a" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 41791 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:26.494343 22345 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.082s	user 0.020s	sys 0.009s
I20260812 06:16:26.592602 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.125253
I20260812 06:16:26.738274 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.145s	user 0.099s	sys 0.032s Metrics: {"bytes_written":8205078,"cfile_init":1,"compiler_manager_pool.queue_time_us":283,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":216,"dirs.run_wall_time_us":863,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":29233,"lbm_writes_lt_1ms":457,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":153,"threads_started":1,"update_count":1000}
I20260812 06:16:26.739475 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 11976772 bytes of WAL
I20260812 06:16:26.739813 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 1 log segments from log reader
I20260812 06:16:26.739886 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000001 (ops 1-6)
I20260812 06:16:26.743131 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:26.743476 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18): 8206538 bytes on disk
I20260812 06:16:26.744130 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:16:26.744527 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:26.763823 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.764380 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:26.899286 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.135s	user 0.103s	sys 0.018s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16487935,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":783,"lbm_read_time_us":7542,"lbm_reads_lt_1ms":360,"lbm_write_time_us":21692,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":273,"threads_started":5,"update_count":1500}
I20260812 06:16:26.900306 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:26.952446 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.052s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18509,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:26.952925 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:26.964218 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4220,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:26.964784 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:27.101941 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.137s	user 0.095s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":10296,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25459,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.102675 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:27.155674 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.053s	user 0.022s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17519,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.156371 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:27.173976 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.174655 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:27.340461 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.166s	user 0.096s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":197,"lbm_read_time_us":13419,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25369,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:27.341207 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:27.387446 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.046s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15668,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.387969 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:27.399463 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.400146 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:27.527889 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.128s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":8151,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25648,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:16:27.528417 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:27.572077 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.044s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17058,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.572604 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:27.583894 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.584486 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:27.715049 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.130s	user 0.117s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1121,"lbm_read_time_us":9237,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25287,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:16:27.715579 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:27.773519 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.058s	user 0.030s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.774188 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:27.785131 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4316,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:27.785660 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:27.933164 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.147s	user 0.100s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":10799,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23806,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:27.933713 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:27.974774 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.041s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15371,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:27.975306 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:28.086912 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.111s	user 0.082s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487817,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":744,"lbm_read_time_us":6738,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21918,"lbm_writes_lt_1ms":343,"mutex_wait_us":278,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:16:28.087651 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:28.124699 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.037s	user 0.018s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15136,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:28.125350 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:28.165481 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.040s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234474,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":299,"dirs.run_wall_time_us":1317,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2069,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:28.166676 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=3.181125
I20260812 06:16:28.179497 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4998,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:28.180032 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 121006379 bytes of WAL
I20260812 06:16:28.180277 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 12 log segments from log reader
I20260812 06:16:28.180325 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000002 (ops 7-11)
I20260812 06:16:28.180359 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000003 (ops 12-16)
I20260812 06:16:28.180434 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000004 (ops 17-20)
I20260812 06:16:28.180481 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000005 (ops 21-25)
I20260812 06:16:28.180523 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000006 (ops 26-30)
I20260812 06:16:28.180591 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000007 (ops 31-35)
I20260812 06:16:28.180639 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000008 (ops 36-40)
I20260812 06:16:28.180682 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000009 (ops 41-45)
I20260812 06:16:28.180727 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000010 (ops 46-50)
I20260812 06:16:28.180770 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000011 (ops 51-55)
I20260812 06:16:28.180817 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000012 (ops 56-60)
I20260812 06:16:28.180863 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000013 (ops 61-65)
I20260812 06:16:28.211270 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.031s	user 0.002s	sys 0.029s Metrics: {}
I20260812 06:16:28.211789 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=3.181125
I20260812 06:16:28.225406 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4718022,"delete_count":0,"lbm_write_time_us":5244,"lbm_writes_lt_1ms":118,"reinsert_count":0,"update_count":575}
I20260812 06:16:28.225948 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18): 471 bytes on disk
I20260812 06:16:28.226398 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:28.226969 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.196750
I20260812 06:16:28.238359 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3320,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:16:28.238919 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:28.422255 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.183s	user 0.143s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795387,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":721,"lbm_read_time_us":12554,"lbm_reads_lt_1ms":674,"lbm_write_time_us":38239,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:16:28.424726 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:28.482136 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.057s	user 0.023s	sys 0.030s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27399,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.482975 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:28.509550 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.026s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.510280 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:28.524266 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5572,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.524709 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:28.701788 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.177s	user 0.152s	sys 0.024s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28795288,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":780,"lbm_read_time_us":14114,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36249,"lbm_writes_lt_1ms":643,"mutex_wait_us":385,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":124032,"update_count":3000}
I20260812 06:16:28.702633 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:28.750752 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.048s	user 0.033s	sys 0.014s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21335,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.751456 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:28.770977 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.019s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:28.771467 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:28.932770 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.161s	user 0.122s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1014,"lbm_read_time_us":9443,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32362,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:16:28.933559 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:28.983870 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.050s	user 0.033s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22102,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:28.984483 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:29.153700 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.169s	user 0.091s	sys 0.068s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20590227,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1583,"lbm_read_time_us":10498,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27730,"lbm_writes_lt_1ms":443,"mutex_wait_us":427,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.154414 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:29.214819 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.060s	user 0.033s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26022,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.215375 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.227450 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.228209 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:29.439744 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.211s	user 0.164s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":406,"lbm_read_time_us":12370,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36528,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:16:29.440508 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:29.500496 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.060s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25146,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:29.501148 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.526641 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.025s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.527163 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.548810 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.021s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.549387 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:29.585968 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.036s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":269,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":147,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1703,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":896}
I20260812 06:16:29.586812 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 112692432 bytes of WAL
I20260812 06:16:29.587085 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 11 log segments from log reader
I20260812 06:16:29.587172 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000014 (ops 66-70)
I20260812 06:16:29.587213 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000015 (ops 71-75)
I20260812 06:16:29.587245 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000016 (ops 76-80)
I20260812 06:16:29.587270 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000017 (ops 81-85)
I20260812 06:16:29.587314 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000018 (ops 86-90)
I20260812 06:16:29.587352 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000019 (ops 91-95)
I20260812 06:16:29.587375 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000020 (ops 96-100)
I20260812 06:16:29.587397 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000021 (ops 101-105)
I20260812 06:16:29.587426 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000022 (ops 106-110)
I20260812 06:16:29.587456 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000023 (ops 111-115)
I20260812 06:16:29.587488 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000024 (ops 116-120)
I20260812 06:16:29.617020 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:29.617687 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.644492 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5640,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.644975 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 11564875 bytes of WAL
I20260812 06:16:29.645220 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 1 log segments from log reader
I20260812 06:16:29.645268 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000025 (ops 121-124)
I20260812 06:16:29.647715 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:29.648017 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.658780 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.659368 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18): 447 bytes on disk
I20260812 06:16:29.659874 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.660365 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:29.914525 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.254s	user 0.159s	sys 0.084s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37000349,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1005,"lbm_read_time_us":18985,"lbm_reads_lt_1ms":875,"lbm_write_time_us":41427,"lbm_writes_lt_1ms":843,"mutex_wait_us":385,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":83,"threads_started":1,"update_count":4000}
I20260812 06:16:29.915772 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=18.063937
I20260812 06:16:29.980502 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.064s	user 0.033s	sys 0.023s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25962,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:29.981091 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:29.998636 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.999122 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:30.219496 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.220s	user 0.151s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795175,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":14369,"lbm_reads_lt_1ms":672,"lbm_write_time_us":40170,"lbm_writes_lt_1ms":643,"mutex_wait_us":89,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:16:30.220281 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=18.063937
I20260812 06:16:30.282733 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.062s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512313,"delete_count":0,"lbm_write_time_us":28296,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:30.283275 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:30.295723 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.012s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.296214 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:30.465006 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.169s	user 0.096s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795169,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1317,"lbm_read_time_us":12119,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36763,"lbm_writes_lt_1ms":643,"mutex_wait_us":388,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:16:30.465999 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:30.533939 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.068s	user 0.022s	sys 0.042s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":32994,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.534611 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:30.552911 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5020,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.553540 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:30.730832 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.177s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692757,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1155,"lbm_read_time_us":11749,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33157,"lbm_writes_lt_1ms":543,"mutex_wait_us":458,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:30.731328 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:30.792574 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.061s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:30.793120 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:30.804859 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.806294 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:31.006496 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.200s	user 0.133s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":813,"lbm_read_time_us":12472,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33256,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:16:31.007063 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=14.095187
I20260812 06:16:31.056757 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.049s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.057265 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:31.099721 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushMRSOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.042s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":320,"dirs.run_wall_time_us":1584,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1830,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:31.100627 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=3.181125
I20260812 06:16:31.124889 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.024s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4389831,"delete_count":0,"lbm_write_time_us":7616,"lbm_writes_lt_1ms":110,"reinsert_count":0,"update_count":535}
I20260812 06:16:31.125411 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 108535612 bytes of WAL
I20260812 06:16:31.125654 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 11 log segments from log reader
I20260812 06:16:31.125721 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000026 (ops 125-129)
I20260812 06:16:31.125785 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000027 (ops 130-134)
I20260812 06:16:31.125844 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000028 (ops 135-139)
I20260812 06:16:31.125891 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000029 (ops 140-144)
I20260812 06:16:31.125934 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000030 (ops 145-148)
I20260812 06:16:31.125977 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000031 (ops 149-153)
I20260812 06:16:31.126019 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000032 (ops 154-158)
I20260812 06:16:31.126062 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000033 (ops 159-163)
I20260812 06:16:31.126106 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000034 (ops 164-168)
I20260812 06:16:31.126156 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000035 (ops 169-172)
I20260812 06:16:31.126199 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000036 (ops 173-177)
I20260812 06:16:31.151656 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:31.152081 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:31.169288 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.017s	user 0.000s	sys 0.010s Metrics: {"bytes_written":3815483,"delete_count":0,"lbm_write_time_us":4456,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:16:31.169737 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling LogGCOp(870d1b57c5084c2bac1706b1a8d07d18): free 12018006 bytes of WAL
I20260812 06:16:31.169941 22517 log_reader.cc:385] T 870d1b57c5084c2bac1706b1a8d07d18: removed 1 log segments from log reader
I20260812 06:16:31.170001 22517 log.cc:1079] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/870d1b57c5084c2bac1706b1a8d07d18/wal-000000037 (ops 178-182)
I20260812 06:16:31.172451 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: LogGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:31.172746 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:31.184988 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.012s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4036,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.185552 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18): 463 bytes on disk
I20260812 06:16:31.185976 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: UndoDeltaBlockGCOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:31.186553 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:31.403540 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.217s	user 0.159s	sys 0.052s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32897815,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":900,"lbm_read_time_us":15866,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37730,"lbm_writes_lt_1ms":743,"mutex_wait_us":602,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:16:31.404131 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=18.063937
I20260812 06:16:31.473311 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.069s	user 0.042s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":31253,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:31.473876 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=2.188937
I20260812 06:16:31.490340 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.490908 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:31.624459 22345 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.130s	user 1.941s	sys 0.161s
I20260812 06:16:31.667173 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.176s	user 0.136s	sys 0.039s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795172,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11643,"lbm_reads_lt_1ms":668,"lbm_write_time_us":41506,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:31.667780 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=10.126437
I20260812 06:16:31.702095 22345 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.077s	user 0.001s	sys 0.000s
I20260812 06:16:31.702867 22345 tablet_server.cc:179] TabletServer@127.21.210.65:0 shutting down...
I20260812 06:16:31.704046 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: FlushDeltaMemStoresOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.036s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15462,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.704625 22613 maintenance_manager.cc:419] P 3f4a7acb55504480ad16844fe7dfde3a: Scheduling MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18): perf score=1.000000
I20260812 06:16:31.799232 22517 maintenance_manager.cc:643] P 3f4a7acb55504480ad16844fe7dfde3a: MajorDeltaCompactionOp(870d1b57c5084c2bac1706b1a8d07d18) complete. Timing: real 0.094s	user 0.069s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16487818,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":2435,"lbm_read_time_us":7549,"lbm_reads_lt_1ms":367,"lbm_write_time_us":16916,"lbm_writes_lt_1ms":343,"mutex_wait_us":78,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2608384,"update_count":1500}
I20260812 06:16:31.800246 22345 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:31.800714 22345 tablet_replica.cc:333] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a: stopping tablet replica
I20260812 06:16:31.800984 22345 raft_consensus.cc:2243] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:31.801255 22345 raft_consensus.cc:2272] T 870d1b57c5084c2bac1706b1a8d07d18 P 3f4a7acb55504480ad16844fe7dfde3a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:31.818630 22345 tablet_server.cc:196] TabletServer@127.21.210.65:0 shutdown complete.
I20260812 06:16:31.831801 22345 master.cc:562] Master@127.21.210.126:43473 shutting down...
I20260812 06:16:31.835872 22345 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:31.836084 22345 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:31.836182 22345 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5c7712edc6824e7fbc2205b3ddfd49ec: stopping tablet replica
I20260812 06:16:31.848928 22345 master.cc:584] Master@127.21.210.126:43473 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5816 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:31.965734 22345 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.210.126:44563
I20260812 06:16:31.966135 22345 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:31.968225 22658 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:31.968421 22657 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:31.968459 22345 server_base.cc:1061] running on GCE node
W20260812 06:16:31.968554 22666 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:31.968788 22345 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:31.968842 22345 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:31.968859 22345 hybrid_clock.cc:648] HybridClock initialized: now 1786515391968859 us; error 0 us; skew 500 ppm
I20260812 06:16:31.969873 22345 webserver.cc:533] Webserver started at http://127.21.210.126:39579/ using document root <none> and password file <none>
I20260812 06:16:31.970069 22345 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:31.970163 22345 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:31.970252 22345 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:31.970809 22345 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/master-0-root/instance:
uuid: "643fc97f9db74a19a22254dd38a9ab4c"
format_stamp: "Formatted at 2026-08-12 06:16:31 on dist-test-slave-7kzw"
I20260812 06:16:31.972328 22345 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:31.973300 22671 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:31.973544 22345 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:31.973637 22345 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/master-0-root
uuid: "643fc97f9db74a19a22254dd38a9ab4c"
format_stamp: "Formatted at 2026-08-12 06:16:31 on dist-test-slave-7kzw"
I20260812 06:16:31.973719 22345 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:31.983843 22345 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:31.984221 22345 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:31.988606 22345 rpc_server.cc:307] RPC server started. Bound to: 127.21.210.126:44563
I20260812 06:16:31.988693 22757 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.210.126:44563 every 8 connection(s)
I20260812 06:16:31.989584 22759 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:31.991607 22759 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c: Bootstrap starting.
I20260812 06:16:31.992439 22759 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:31.993548 22759 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c: No bootstrap required, opened a new log
I20260812 06:16:31.994019 22759 raft_consensus.cc:359] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER }
I20260812 06:16:31.994107 22759 raft_consensus.cc:385] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:31.994132 22759 raft_consensus.cc:740] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 643fc97f9db74a19a22254dd38a9ab4c, State: Initialized, Role: FOLLOWER
I20260812 06:16:31.994302 22759 consensus_queue.cc:260] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER }
I20260812 06:16:31.994378 22759 raft_consensus.cc:399] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:31.994426 22759 raft_consensus.cc:493] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:31.994546 22759 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:31.995304 22759 raft_consensus.cc:515] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER }
I20260812 06:16:31.995460 22759 leader_election.cc:304] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 643fc97f9db74a19a22254dd38a9ab4c; no voters: 
I20260812 06:16:31.995674 22759 leader_election.cc:290] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:31.995915 22762 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:31.996165 22759 sys_catalog.cc:565] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:31.996218 22762 raft_consensus.cc:697] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 1 LEADER]: Becoming Leader. State: Replica: 643fc97f9db74a19a22254dd38a9ab4c, State: Running, Role: LEADER
I20260812 06:16:31.996357 22762 consensus_queue.cc:237] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER }
I20260812 06:16:31.996959 22764 sys_catalog.cc:455] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 643fc97f9db74a19a22254dd38a9ab4c. Latest consensus state: current_term: 1 leader_uuid: "643fc97f9db74a19a22254dd38a9ab4c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER } }
I20260812 06:16:31.997056 22764 sys_catalog.cc:458] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:31.997262 22763 sys_catalog.cc:455] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "643fc97f9db74a19a22254dd38a9ab4c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "643fc97f9db74a19a22254dd38a9ab4c" member_type: VOTER } }
I20260812 06:16:31.997431 22763 sys_catalog.cc:458] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:31.997797 22772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:31.998775 22772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:31.999001 22345 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:32.000910 22772 catalog_manager.cc:1383] Generated new cluster ID: 438550b5a6df442fb640c98824ff53fd
I20260812 06:16:32.000979 22772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:32.006201 22772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:32.006907 22772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:32.014415 22772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c: Generated new TSK 0
I20260812 06:16:32.014658 22772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:32.031472 22345 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:32.033602 22785 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:32.033622 22788 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:32.033833 22345 server_base.cc:1061] running on GCE node
W20260812 06:16:32.033627 22786 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:32.034201 22345 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:32.034265 22345 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:32.034291 22345 hybrid_clock.cc:648] HybridClock initialized: now 1786515392034289 us; error 0 us; skew 500 ppm
I20260812 06:16:32.035362 22345 webserver.cc:533] Webserver started at http://127.21.210.65:39449/ using document root <none> and password file <none>
I20260812 06:16:32.035569 22345 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:32.035648 22345 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:32.035729 22345 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:32.036177 22345 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/instance:
uuid: "346f93a5e8b748f9bc0e531259175f31"
format_stamp: "Formatted at 2026-08-12 06:16:32 on dist-test-slave-7kzw"
I20260812 06:16:32.037741 22345 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:32.038789 22798 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:32.039047 22345 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:32.039139 22345 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root
uuid: "346f93a5e8b748f9bc0e531259175f31"
format_stamp: "Formatted at 2026-08-12 06:16:32 on dist-test-slave-7kzw"
I20260812 06:16:32.039227 22345 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:32.046391 22345 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:32.046759 22345 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:32.047048 22345 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:32.047511 22345 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:32.047577 22345 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:32.047638 22345 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:32.047691 22345 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:32.052083 22345 rpc_server.cc:307] RPC server started. Bound to: 127.21.210.65:44543
I20260812 06:16:32.052160 22911 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.210.65:44543 every 8 connection(s)
I20260812 06:16:32.063658 22915 heartbeater.cc:344] Connected to a master server at 127.21.210.126:44563
I20260812 06:16:32.063774 22915 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:32.064035 22915 heartbeater.cc:507] Master 127.21.210.126:44563 requested a full tablet report, sending...
I20260812 06:16:32.064805 22698 ts_manager.cc:194] Registered new tserver with Master: 346f93a5e8b748f9bc0e531259175f31 (127.21.210.65:44543)
I20260812 06:16:32.064889 22345 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012308905s
I20260812 06:16:32.065831 22698 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55390
I20260812 06:16:32.072873 22698 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55396:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:32.082404 22854 tablet_service.cc:1511] Processing CreateTablet for tablet f0571bac0bc645da9eb80c404ec1ba24 (DEFAULT_TABLE table=heavy-update-compaction-test [id=47856e2dfdf34e938c4fbdf906d5cd51]), partition=
I20260812 06:16:32.082767 22854 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet f0571bac0bc645da9eb80c404ec1ba24. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:32.084993 22935 tablet_bootstrap.cc:492] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Bootstrap starting.
I20260812 06:16:32.085901 22935 tablet_bootstrap.cc:654] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:32.087006 22935 tablet_bootstrap.cc:492] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: No bootstrap required, opened a new log
I20260812 06:16:32.087083 22935 ts_tablet_manager.cc:1403] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:32.087517 22935 raft_consensus.cc:359] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "346f93a5e8b748f9bc0e531259175f31" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 44543 } }
I20260812 06:16:32.087602 22935 raft_consensus.cc:385] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:32.087625 22935 raft_consensus.cc:740] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 346f93a5e8b748f9bc0e531259175f31, State: Initialized, Role: FOLLOWER
I20260812 06:16:32.087786 22935 consensus_queue.cc:260] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [NON_LEADER]: Queue going to NON_LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 0, Majority size: -1, State: 0, Mode: NON_LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "346f93a5e8b748f9bc0e531259175f31" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 44543 } }
I20260812 06:16:32.087888 22935 raft_consensus.cc:399] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:32.087939 22935 raft_consensus.cc:493] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:32.088016 22935 raft_consensus.cc:3060] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:32.088798 22935 raft_consensus.cc:515] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "346f93a5e8b748f9bc0e531259175f31" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 44543 } }
I20260812 06:16:32.088966 22935 leader_election.cc:304] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [CANDIDATE]: Term 1 election: Election decided. Result: candidate won. Election summary: received 1 responses out of 1 voters: 1 yes votes; 0 no votes. yes voters: 346f93a5e8b748f9bc0e531259175f31; no voters: 
I20260812 06:16:32.089183 22935 leader_election.cc:290] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:32.089401 22937 raft_consensus.cc:2804] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:32.089605 22935 ts_tablet_manager.cc:1434] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:16:32.089648 22915 heartbeater.cc:499] Master 127.21.210.126:44563 was elected leader, sending a full tablet report...
I20260812 06:16:32.089933 22937 raft_consensus.cc:697] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 1 LEADER]: Becoming Leader. State: Replica: 346f93a5e8b748f9bc0e531259175f31, State: Running, Role: LEADER
I20260812 06:16:32.090081 22937 consensus_queue.cc:237] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [LEADER]: Queue going to LEADER mode. State: All replicated index: 0, Majority replicated index: 0, Committed index: 0, Last appended: 0.0, Last appended by leader: 0, Current term: 1, Majority size: 1, State: 0, Mode: LEADER, active raft config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "346f93a5e8b748f9bc0e531259175f31" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 44543 } }
I20260812 06:16:32.091519 22698 catalog_manager.cc:5719] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 reported cstate change: term changed from 0 to 1, leader changed from <none> to 346f93a5e8b748f9bc0e531259175f31 (127.21.210.65). New cstate: current_term: 1 leader_uuid: "346f93a5e8b748f9bc0e531259175f31" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "346f93a5e8b748f9bc0e531259175f31" member_type: VOTER last_known_addr { host: "127.21.210.65" port: 44543 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:32.151779 22345 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.003s
I20260812 06:16:32.303050 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=19.054940
I20260812 06:16:32.461898 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.159s	user 0.135s	sys 0.020s Metrics: {"bytes_written":12389538,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":297,"dirs.run_wall_time_us":1040,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37408,"lbm_writes_lt_1ms":759,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":5504,"update_count":1510}
I20260812 06:16:32.462693 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 20743831 bytes of WAL
I20260812 06:16:32.463009 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 2 log segments from log reader
I20260812 06:16:32.463102 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000001 (ops 1-6)
I20260812 06:16:32.463177 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000002 (ops 7-11)
I20260812 06:16:32.469108 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:32.469659 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24): 16411393 bytes on disk
I20260812 06:16:32.470263 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":111,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.470758 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:32.505607 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.035s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4258,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:32.506222 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:32.522440 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.523137 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:32.724866 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.201s	user 0.125s	sys 0.066s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":657,"lbm_read_time_us":13908,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31262,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":335,"threads_started":5,"update_count":2500}
I20260812 06:16:32.725445 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:32.780300 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.055s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.780745 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:32.803120 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.022s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.803686 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:32.990535 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.187s	user 0.139s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":12711,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28275,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:32.991253 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:33.036235 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.045s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19653,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.036901 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:33.057363 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.020s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.057824 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:33.241793 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.184s	user 0.103s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":597,"lbm_read_time_us":11325,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27978,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:16:33.242527 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=15.087375
I20260812 06:16:33.296288 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.054s	user 0.026s	sys 0.021s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22272,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:16:33.296833 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:33.307724 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.308141 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:33.317499 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3565,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.317902 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:33.553438 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.235s	user 0.136s	sys 0.096s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877207,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":228,"lbm_read_time_us":14922,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40138,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":3000}
I20260812 06:16:33.554136 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:33.599926 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.046s	user 0.030s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19188,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.600620 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:33.623980 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.624496 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:33.821794 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.197s	user 0.136s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1053,"lbm_read_time_us":14224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30114,"lbm_writes_lt_1ms":543,"mutex_wait_us":352,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":48384,"update_count":2500}
I20260812 06:16:33.822485 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:33.880388 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.058s	user 0.031s	sys 0.024s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24124,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:16:33.880961 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:33.893438 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.893968 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:33.935109 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.041s	user 0.030s	sys 0.011s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1400,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1645,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:33.935804 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 120553379 bytes of WAL
I20260812 06:16:33.936048 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 12 log segments from log reader
I20260812 06:16:33.936091 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000003 (ops 12-16)
I20260812 06:16:33.936121 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000004 (ops 17-20)
I20260812 06:16:33.936190 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000005 (ops 21-25)
I20260812 06:16:33.936245 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000006 (ops 26-30)
I20260812 06:16:33.936300 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000007 (ops 31-34)
I20260812 06:16:33.936342 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000008 (ops 35-39)
I20260812 06:16:33.936381 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000009 (ops 40-44)
I20260812 06:16:33.936425 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000010 (ops 45-49)
I20260812 06:16:33.936465 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000011 (ops 50-54)
I20260812 06:16:33.936506 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000012 (ops 55-59)
I20260812 06:16:33.936543 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000013 (ops 60-64)
I20260812 06:16:33.936582 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000014 (ops 65-69)
I20260812 06:16:33.964282 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:33.964679 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24): 482 bytes on disk
I20260812 06:16:33.965092 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.965647 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=3.181125
I20260812 06:16:33.995090 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.029s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6294,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:33.995568 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 12017983 bytes of WAL
I20260812 06:16:33.995811 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 1 log segments from log reader
I20260812 06:16:33.995857 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000015 (ops 70-74)
I20260812 06:16:33.998781 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:33.999147 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:34.010454 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.011148 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:34.255849 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.245s	user 0.169s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":702,"lbm_read_time_us":15599,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40378,"lbm_writes_lt_1ms":743,"mutex_wait_us":132,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:16:34.256634 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=18.063937
I20260812 06:16:34.331996 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.075s	user 0.044s	sys 0.020s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":29700,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.332506 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:34.342887 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3943,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.343309 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:34.569438 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.226s	user 0.141s	sys 0.075s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":636,"lbm_read_time_us":14640,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38046,"lbm_writes_lt_1ms":643,"mutex_wait_us":334,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":60416,"update_count":3000}
I20260812 06:16:34.570086 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=18.063937
I20260812 06:16:34.645509 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.075s	user 0.041s	sys 0.020s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":28814,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.645972 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:34.656803 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.657541 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:34.861543 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.204s	user 0.136s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1005,"lbm_read_time_us":14663,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35009,"lbm_writes_lt_1ms":643,"mutex_wait_us":51,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:16:34.862260 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=15.087375
I20260812 06:16:34.916091 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.054s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23486,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:34.916587 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:34.941968 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5178,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.942540 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:34.954641 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4383,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.955325 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:35.192094 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.237s	user 0.149s	sys 0.084s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":361,"lbm_read_time_us":16015,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39108,"lbm_writes_lt_1ms":643,"mutex_wait_us":83,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:35.192910 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=16.079562
I20260812 06:16:35.253078 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.060s	user 0.037s	sys 0.016s Metrics: {"bytes_written":17681652,"delete_count":0,"lbm_write_time_us":25225,"lbm_writes_lt_1ms":434,"reinsert_count":0,"update_count":2155}
I20260812 06:16:35.253589 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:35.264602 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3241134,"delete_count":0,"lbm_write_time_us":3236,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:16:35.265030 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:35.274940 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3731,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.275372 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:35.485320 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.210s	user 0.113s	sys 0.096s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877191,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":432,"lbm_read_time_us":14627,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36435,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:35.486030 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:35.540155 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.054s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24708,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:35.540889 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=3.181125
I20260812 06:16:35.558141 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:35.558732 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:35.568667 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3629,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.569135 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:35.604184 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1354,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2268,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:35.604842 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 125163336 bytes of WAL
I20260812 06:16:35.605065 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 12 log segments from log reader
I20260812 06:16:35.605129 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000016 (ops 75-79)
I20260812 06:16:35.605188 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000017 (ops 80-84)
I20260812 06:16:35.605247 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000018 (ops 85-89)
I20260812 06:16:35.605289 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000019 (ops 90-94)
I20260812 06:16:35.605326 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000020 (ops 95-99)
I20260812 06:16:35.605366 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000021 (ops 100-104)
I20260812 06:16:35.605404 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000022 (ops 105-109)
I20260812 06:16:35.605443 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000023 (ops 110-114)
I20260812 06:16:35.605481 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000024 (ops 115-119)
I20260812 06:16:35.605521 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000025 (ops 120-124)
I20260812 06:16:35.605561 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000026 (ops 125-129)
I20260812 06:16:35.605599 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000027 (ops 130-135)
I20260812 06:16:35.633085 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:35.633569 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=3.181125
I20260812 06:16:35.652149 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7450,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:35.652623 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24): 492 bytes on disk
I20260812 06:16:35.653062 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:16:35.653561 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:35.665339 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4129,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.666033 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:35.938462 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.272s	user 0.181s	sys 0.087s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082260,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":2961,"lbm_read_time_us":18228,"lbm_reads_lt_1ms":875,"lbm_write_time_us":47279,"lbm_writes_lt_1ms":843,"mutex_wait_us":68,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":7296,"thread_start_us":85,"threads_started":1,"update_count":4000}
I20260812 06:16:35.939332 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=18.063937
I20260812 06:16:35.992398 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.053s	user 0.044s	sys 0.006s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":23220,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:35.992897 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:36.023733 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.031s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5656,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.024201 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:36.035216 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4281,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.035987 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:36.226286 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.190s	user 0.141s	sys 0.048s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979635,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":988,"lbm_read_time_us":14153,"lbm_reads_lt_1ms":773,"lbm_write_time_us":41093,"lbm_writes_lt_1ms":743,"mutex_wait_us":1162,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":3500}
I20260812 06:16:36.226996 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:36.275528 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.048s	user 0.045s	sys 0.003s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21751,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:36.276100 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:36.292302 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.016s	user 0.013s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.292940 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:36.447932 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.155s	user 0.112s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":337,"lbm_read_time_us":10087,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30942,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:16:36.448745 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=12.110812
I20260812 06:16:36.489910 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.041s	user 0.025s	sys 0.013s Metrics: {"bytes_written":13579241,"delete_count":0,"lbm_write_time_us":17930,"lbm_writes_lt_1ms":334,"reinsert_count":0,"update_count":1655}
I20260812 06:16:36.490392 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.196750
I20260812 06:16:36.501466 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3661,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:16:36.501950 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:36.649225 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.147s	user 0.097s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":785,"lbm_read_time_us":9081,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23091,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:16:36.649991 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:36.697427 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.047s	user 0.025s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21202,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:36.697942 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:36.722105 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.024s	user 0.006s	sys 0.014s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.722805 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:36.927421 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.204s	user 0.151s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":188,"lbm_read_time_us":14898,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32239,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:36.928354 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=11.118625
I20260812 06:16:36.972851 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":19283,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:36.973857 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:36.987982 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4418,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:36.988945 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:37.030279 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushMRSOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.041s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1236,"drs_written":1,"lbm_read_time_us":135,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2298,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:37.031072 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24): 447 bytes on disk
I20260812 06:16:37.031610 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: UndoDeltaBlockGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:16:37.032207 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=3.181125
I20260812 06:16:37.054257 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.022s	user 0.002s	sys 0.016s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":4733,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:37.054916 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 112239612 bytes of WAL
I20260812 06:16:37.055202 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 11 log segments from log reader
I20260812 06:16:37.055253 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000028 (ops 136-140)
I20260812 06:16:37.055289 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000029 (ops 141-145)
I20260812 06:16:37.055351 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000030 (ops 146-150)
I20260812 06:16:37.055393 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000031 (ops 151-154)
I20260812 06:16:37.055439 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000032 (ops 155-159)
I20260812 06:16:37.055482 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000033 (ops 160-164)
I20260812 06:16:37.055522 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000034 (ops 165-169)
I20260812 06:16:37.055562 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000035 (ops 170-174)
I20260812 06:16:37.055603 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000036 (ops 175-179)
I20260812 06:16:37.055641 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000037 (ops 180-184)
I20260812 06:16:37.055682 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000038 (ops 185-189)
I20260812 06:16:37.082119 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:16:37.082815 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=2.188937
I20260812 06:16:37.098601 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.016s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":450}
I20260812 06:16:37.099124 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling LogGCOp(f0571bac0bc645da9eb80c404ec1ba24): free 12017954 bytes of WAL
I20260812 06:16:37.099458 22812 log_reader.cc:385] T f0571bac0bc645da9eb80c404ec1ba24: removed 1 log segments from log reader
I20260812 06:16:37.099524 22812 log.cc:1079] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: Deleting log segment in path: /tmp/dist-test-taskexmfEB/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515386121339-22345-0/minicluster-data/ts-0-root/wals/f0571bac0bc645da9eb80c404ec1ba24/wal-000000039 (ops 190-194)
I20260812 06:16:37.102648 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: LogGCOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:37.103008 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=1.000000
I20260812 06:16:37.272013 22345 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.120s	user 1.854s	sys 0.177s
I20260812 06:16:37.307627 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: MajorDeltaCompactionOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.204s	user 0.153s	sys 0.050s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877321,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15659,"lbm_reads_lt_1ms":662,"lbm_write_time_us":34514,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":3000}
I20260812 06:16:37.308197 22916 maintenance_manager.cc:419] P 346f93a5e8b748f9bc0e531259175f31: Scheduling FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24): perf score=14.095187
I20260812 06:16:37.339253 22345 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.002s	sys 0.000s
I20260812 06:16:37.339799 22345 tablet_server.cc:179] TabletServer@127.21.210.65:0 shutting down...
I20260812 06:16:37.357625 22812 maintenance_manager.cc:643] P 346f93a5e8b748f9bc0e531259175f31: FlushDeltaMemStoresOp(f0571bac0bc645da9eb80c404ec1ba24) complete. Timing: real 0.049s	user 0.017s	sys 0.029s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22342,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:37.358341 22345 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:37.358630 22345 tablet_replica.cc:333] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31: stopping tablet replica
I20260812 06:16:37.358800 22345 raft_consensus.cc:2243] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:37.369505 22345 raft_consensus.cc:2272] T f0571bac0bc645da9eb80c404ec1ba24 P 346f93a5e8b748f9bc0e531259175f31 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:37.384155 22345 tablet_server.cc:196] TabletServer@127.21.210.65:0 shutdown complete.
I20260812 06:16:37.387270 22345 master.cc:562] Master@127.21.210.126:44563 shutting down...
I20260812 06:16:37.390774 22345 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:37.390955 22345 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:37.391036 22345 tablet_replica.cc:333] T 00000000000000000000000000000000 P 643fc97f9db74a19a22254dd38a9ab4c: stopping tablet replica
I20260812 06:16:37.403488 22345 master.cc:584] Master@127.21.210.126:44563 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5543 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11361 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test suite ran. (11361 ms total)
[  PASSED  ] 2 tests.
