[==========] 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:37.059329 14986 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.162.190:44905
I20260812 06:16:37.060281 14986 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:37.060858 14986 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.067097 14999 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:37.067092 14995 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:37.067291 14986 server_base.cc:1061] running on GCE node
W20260812 06:16:37.067363 14996 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:37.067801 14986 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.067921 14986 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:37.067965 14986 hybrid_clock.cc:648] HybridClock initialized: now 1786515397067962 us; error 0 us; skew 500 ppm
I20260812 06:16:37.069684 14986 webserver.cc:533] Webserver started at http://127.14.162.190:44963/ using document root <none> and password file <none>
I20260812 06:16:37.070194 14986 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.070278 14986 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.070514 14986 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.072082 14986 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/master-0-root/instance:
uuid: "52752cbf091140ec964c39100c035f0e"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-8hhm"
I20260812 06:16:37.075350 14986 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:16:37.077296 15006 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:37.078241 14986 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.078368 14986 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/master-0-root
uuid: "52752cbf091140ec964c39100c035f0e"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-8hhm"
I20260812 06:16:37.078465 14986 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-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:37.103402 14986 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.104079 14986 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:37.104266 14986 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.112648 14986 rpc_server.cc:307] RPC server started. Bound to: 127.14.162.190:44905
I20260812 06:16:37.112658 15094 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.162.190:44905 every 8 connection(s)
I20260812 06:16:37.115002 15095 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:37.120553 15095 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: Bootstrap starting.
I20260812 06:16:37.122997 15095 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.123931 15095 log.cc:826] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:37.125828 15095 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: No bootstrap required, opened a new log
I20260812 06:16:37.128635 15095 raft_consensus.cc:359] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "52752cbf091140ec964c39100c035f0e" member_type: VOTER }
I20260812 06:16:37.128839 15095 raft_consensus.cc:385] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.128957 15095 raft_consensus.cc:740] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 52752cbf091140ec964c39100c035f0e, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.129606 15095 consensus_queue.cc:260] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [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: "52752cbf091140ec964c39100c035f0e" member_type: VOTER }
I20260812 06:16:37.129747 15095 raft_consensus.cc:399] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.129833 15095 raft_consensus.cc:493] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.130004 15095 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.130800 15095 raft_consensus.cc:515] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "52752cbf091140ec964c39100c035f0e" member_type: VOTER }
I20260812 06:16:37.131244 15095 leader_election.cc:304] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [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: 52752cbf091140ec964c39100c035f0e; no voters: 
I20260812 06:16:37.131564 15095 leader_election.cc:290] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.131740 15100 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.131991 15100 raft_consensus.cc:697] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 1 LEADER]: Becoming Leader. State: Replica: 52752cbf091140ec964c39100c035f0e, State: Running, Role: LEADER
I20260812 06:16:37.132426 15100 consensus_queue.cc:237] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [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: "52752cbf091140ec964c39100c035f0e" member_type: VOTER }
I20260812 06:16:37.132584 15095 sys_catalog.cc:565] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:37.134275 15106 sys_catalog.cc:455] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "52752cbf091140ec964c39100c035f0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "52752cbf091140ec964c39100c035f0e" member_type: VOTER } }
I20260812 06:16:37.134325 15107 sys_catalog.cc:455] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [sys.catalog]: SysCatalogTable state changed. Reason: New leader 52752cbf091140ec964c39100c035f0e. Latest consensus state: current_term: 1 leader_uuid: "52752cbf091140ec964c39100c035f0e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "52752cbf091140ec964c39100c035f0e" member_type: VOTER } }
I20260812 06:16:37.134395 15106 sys_catalog.cc:458] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.134431 15107 sys_catalog.cc:458] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:37.134910 15123 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:37.135146 14986 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:37.137132 15123 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:37.141448 15123 catalog_manager.cc:1383] Generated new cluster ID: 9bc0e0c05bc8471cb2521a6a209bc166
I20260812 06:16:37.141506 15123 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:37.150213 15123 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:37.151330 15123 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:37.158874 15123 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: Generated new TSK 0
I20260812 06:16:37.159547 15123 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:37.167536 14986 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:37.170181 15136 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:37.170241 15135 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:37.170233 15139 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:37.170871 14986 server_base.cc:1061] running on GCE node
I20260812 06:16:37.171060 14986 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:37.171118 14986 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:37.171142 14986 hybrid_clock.cc:648] HybridClock initialized: now 1786515397171142 us; error 0 us; skew 500 ppm
I20260812 06:16:37.172111 14986 webserver.cc:533] Webserver started at http://127.14.162.129:41301/ using document root <none> and password file <none>
I20260812 06:16:37.172276 14986 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:37.172345 14986 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:37.172421 14986 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:37.172797 14986 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/instance:
uuid: "d3324622954546758318095617f1c7a7"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-8hhm"
I20260812 06:16:37.174393 14986 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:37.175384 15149 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:37.175631 14986 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:37.175701 14986 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root
uuid: "d3324622954546758318095617f1c7a7"
format_stamp: "Formatted at 2026-08-12 06:16:37 on dist-test-slave-8hhm"
I20260812 06:16:37.175783 14986 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-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:37.196434 14986 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:37.196925 14986 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:37.197523 14986 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:37.198464 14986 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:37.198516 14986 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.198583 14986 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:37.198624 14986 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:37.205403 14986 rpc_server.cc:307] RPC server started. Bound to: 127.14.162.129:41127
I20260812 06:16:37.205436 15267 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.162.129:41127 every 8 connection(s)
I20260812 06:16:37.219127 15268 heartbeater.cc:344] Connected to a master server at 127.14.162.190:44905
I20260812 06:16:37.219408 15268 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:37.219902 15268 heartbeater.cc:507] Master 127.14.162.190:44905 requested a full tablet report, sending...
I20260812 06:16:37.221407 15037 ts_manager.cc:194] Registered new tserver with Master: d3324622954546758318095617f1c7a7 (127.14.162.129:41127)
I20260812 06:16:37.221671 14986 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015607976s
I20260812 06:16:37.223002 15037 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45862
I20260812 06:16:37.231096 15037 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45878:
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:37.244825 15191 tablet_service.cc:1511] Processing CreateTablet for tablet d08cb4824a55439a9aa6471da38597c8 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1909d9281d49418494502c07d8de7aba]), partition=
I20260812 06:16:37.245317 15191 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d08cb4824a55439a9aa6471da38597c8. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:37.247471 15292 tablet_bootstrap.cc:492] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Bootstrap starting.
I20260812 06:16:37.248342 15292 tablet_bootstrap.cc:654] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:37.249574 15292 tablet_bootstrap.cc:492] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: No bootstrap required, opened a new log
I20260812 06:16:37.249656 15292 ts_tablet_manager.cc:1403] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:37.250168 15292 raft_consensus.cc:359] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3324622954546758318095617f1c7a7" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 41127 } }
I20260812 06:16:37.250264 15292 raft_consensus.cc:385] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:37.250289 15292 raft_consensus.cc:740] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d3324622954546758318095617f1c7a7, State: Initialized, Role: FOLLOWER
I20260812 06:16:37.250429 15292 consensus_queue.cc:260] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [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: "d3324622954546758318095617f1c7a7" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 41127 } }
I20260812 06:16:37.250499 15292 raft_consensus.cc:399] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:37.250564 15292 raft_consensus.cc:493] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:37.250638 15292 raft_consensus.cc:3060] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:37.251652 15292 raft_consensus.cc:515] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3324622954546758318095617f1c7a7" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 41127 } }
I20260812 06:16:37.251808 15292 leader_election.cc:304] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [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: d3324622954546758318095617f1c7a7; no voters: 
I20260812 06:16:37.252064 15292 leader_election.cc:290] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:37.252184 15294 raft_consensus.cc:2804] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:37.252391 15292 ts_tablet_manager.cc:1434] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:37.252540 15294 raft_consensus.cc:697] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 1 LEADER]: Becoming Leader. State: Replica: d3324622954546758318095617f1c7a7, State: Running, Role: LEADER
I20260812 06:16:37.252774 15268 heartbeater.cc:499] Master 127.14.162.190:44905 was elected leader, sending a full tablet report...
I20260812 06:16:37.252863 15294 consensus_queue.cc:237] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [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: "d3324622954546758318095617f1c7a7" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 41127 } }
I20260812 06:16:37.255421 15037 catalog_manager.cc:5719] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 reported cstate change: term changed from 0 to 1, leader changed from <none> to d3324622954546758318095617f1c7a7 (127.14.162.129). New cstate: current_term: 1 leader_uuid: "d3324622954546758318095617f1c7a7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d3324622954546758318095617f1c7a7" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 41127 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:37.322320 14986 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.024s	sys 0.003s
I20260812 06:16:37.456750 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushMRSOp(d08cb4824a55439a9aa6471da38597c8): perf score=18.062753
I20260812 06:16:37.604874 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushMRSOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.148s	user 0.113s	sys 0.027s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":285,"delete_count":0,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":942,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":35587,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":106,"threads_started":1,"update_count":1050}
I20260812 06:16:37.605986 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling LogGCOp(d08cb4824a55439a9aa6471da38597c8): free 20743880 bytes of WAL
I20260812 06:16:37.606319 15157 log_reader.cc:385] T d08cb4824a55439a9aa6471da38597c8: removed 2 log segments from log reader
I20260812 06:16:37.606386 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000001 (ops 1-6)
I20260812 06:16:37.606465 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000002 (ops 7-11)
I20260812 06:16:37.611948 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: LogGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:37.612311 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8): 16411392 bytes on disk
I20260812 06:16:37.612928 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8) 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:37.613366 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:37.629778 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6170,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.630272 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:37.742650 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.112s	user 0.075s	sys 0.027s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":432,"lbm_read_time_us":5705,"lbm_reads_lt_1ms":364,"lbm_write_time_us":19213,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":225,"threads_started":5,"update_count":1500}
I20260812 06:16:37.743175 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:37.787531 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.044s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14391,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.788041 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:37.798767 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.799427 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:37.933357 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.134s	user 0.099s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":425,"lbm_read_time_us":7332,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26249,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:37.933908 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:37.981467 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.047s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14560,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:37.982013 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:37.992676 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.993072 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.144771 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.151s	user 0.113s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":275,"lbm_read_time_us":10117,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25861,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2000}
I20260812 06:16:38.145267 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:38.191325 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.046s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20747,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.191792 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:38.202550 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.203166 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.321729 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.118s	user 0.088s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":598,"lbm_read_time_us":8743,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21845,"lbm_writes_lt_1ms":443,"mutex_wait_us":222,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:16:38.322440 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:38.359673 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.037s	user 0.017s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15301,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.360096 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:38.375067 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5823,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.375568 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.493017 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.117s	user 0.105s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":990,"lbm_read_time_us":8480,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22231,"lbm_writes_lt_1ms":443,"mutex_wait_us":99,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:38.493743 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:38.536844 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.043s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15284,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.537441 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:38.547792 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.548209 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.693367 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.145s	user 0.094s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":11001,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23122,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:16:38.694204 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:38.740649 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.046s	user 0.027s	sys 0.001s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13607,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.741120 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:38.752383 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4232,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.753087 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.879388 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.126s	user 0.107s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":944,"lbm_read_time_us":8700,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24219,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.880077 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=10.126437
I20260812 06:16:38.916072 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.036s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:38.916564 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:38.932345 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.016s	user 0.000s	sys 0.014s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.933020 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushMRSOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:38.966234 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushMRSOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1376,"drs_written":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1600,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":1792}
I20260812 06:16:38.967043 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling LogGCOp(d08cb4824a55439a9aa6471da38597c8): free 121006429 bytes of WAL
I20260812 06:16:38.967267 15157 log_reader.cc:385] T d08cb4824a55439a9aa6471da38597c8: removed 12 log segments from log reader
I20260812 06:16:38.967324 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000003 (ops 12-16)
I20260812 06:16:38.967376 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000004 (ops 17-21)
I20260812 06:16:38.967417 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000005 (ops 22-26)
I20260812 06:16:38.967468 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000006 (ops 27-31)
I20260812 06:16:38.967504 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000007 (ops 32-36)
I20260812 06:16:38.967545 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000008 (ops 37-41)
I20260812 06:16:38.967588 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000009 (ops 42-46)
I20260812 06:16:38.967629 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000010 (ops 47-51)
I20260812 06:16:38.967674 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000011 (ops 52-56)
I20260812 06:16:38.967716 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000012 (ops 57-60)
I20260812 06:16:38.967758 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000013 (ops 61-65)
I20260812 06:16:38.967799 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000014 (ops 66-70)
I20260812 06:16:38.993660 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: LogGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.026s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:38.994159 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=6.157687
I20260812 06:16:39.019187 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.025s	user 0.021s	sys 0.000s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":9365,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:39.019769 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling LogGCOp(d08cb4824a55439a9aa6471da38597c8): free 12017927 bytes of WAL
I20260812 06:16:39.020035 15157 log_reader.cc:385] T d08cb4824a55439a9aa6471da38597c8: removed 1 log segments from log reader
I20260812 06:16:39.020105 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000015 (ops 71-75)
I20260812 06:16:39.022383 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: LogGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:39.022706 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8): 492 bytes on disk
I20260812 06:16:39.023111 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.023622 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:39.189373 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.166s	user 0.124s	sys 0.041s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":457,"lbm_read_time_us":11749,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33277,"lbm_writes_lt_1ms":643,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:16:39.189901 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:39.248570 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.058s	user 0.030s	sys 0.020s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":24153,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.249078 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:39.260756 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4206,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.261188 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:39.419878 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.158s	user 0.103s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":11324,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29807,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:16:39.420442 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:39.474246 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.054s	user 0.046s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.474799 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:39.485965 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.486689 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:39.637050 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.150s	user 0.118s	sys 0.028s 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":329,"lbm_read_time_us":10233,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29535,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:16:39.637856 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=11.118625
I20260812 06:16:39.671166 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.033s	user 0.011s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14110,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.671706 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:39.697288 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.025s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5354,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.697808 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:39.708144 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.708626 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:39.860989 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.152s	user 0.118s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":625,"lbm_read_time_us":10483,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27112,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":31104,"update_count":2500}
I20260812 06:16:39.861634 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:39.922470 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.061s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22335,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.923046 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:39.933292 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.934297 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:40.107750 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.173s	user 0.104s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":518,"lbm_read_time_us":11399,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28179,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:16:40.108539 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:40.170783 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.062s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22368,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.171310 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:40.182060 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4138,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.182559 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:40.373803 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.191s	user 0.134s	sys 0.052s 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":1001,"lbm_read_time_us":12841,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32370,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:16:40.374642 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:40.438383 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.064s	user 0.053s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28075,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.439147 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:40.455772 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6353,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.456559 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushMRSOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:40.496373 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushMRSOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.040s	user 0.034s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1392,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1835,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:40.497285 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling LogGCOp(d08cb4824a55439a9aa6471da38597c8): free 124257272 bytes of WAL
I20260812 06:16:40.497622 15157 log_reader.cc:385] T d08cb4824a55439a9aa6471da38597c8: removed 12 log segments from log reader
I20260812 06:16:40.497728 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000016 (ops 76-80)
I20260812 06:16:40.497786 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000017 (ops 81-85)
I20260812 06:16:40.497834 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000018 (ops 86-90)
I20260812 06:16:40.497864 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000019 (ops 91-95)
I20260812 06:16:40.497891 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000020 (ops 96-100)
I20260812 06:16:40.497929 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000021 (ops 101-105)
I20260812 06:16:40.497957 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000022 (ops 106-110)
I20260812 06:16:40.497994 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000023 (ops 111-114)
I20260812 06:16:40.498021 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000024 (ops 115-119)
I20260812 06:16:40.498059 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000025 (ops 120-124)
I20260812 06:16:40.498095 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000026 (ops 125-129)
I20260812 06:16:40.498131 15157 log.cc:1079] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/d08cb4824a55439a9aa6471da38597c8/wal-000000027 (ops 130-134)
I20260812 06:16:40.528700 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: LogGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.031s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:40.529176 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=5.165500
I20260812 06:16:40.547792 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.018s	user 0.004s	sys 0.012s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":7777,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:40.548312 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:40.556067 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.008s	user 0.002s	sys 0.003s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2553,"lbm_writes_lt_1ms":48,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":225}
I20260812 06:16:40.556545 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:40.769484 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.213s	user 0.137s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":997,"lbm_read_time_us":15832,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36661,"lbm_writes_lt_1ms":743,"mutex_wait_us":37,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13184,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:16:40.770154 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8): 483 bytes on disk
I20260812 06:16:40.770655 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: UndoDeltaBlockGCOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.771550 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=18.063937
I20260812 06:16:40.848822 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.077s	user 0.032s	sys 0.036s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":34039,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:16:40.849642 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=3.181125
I20260812 06:16:40.861491 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4349,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.861920 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:40.878419 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5419,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.878891 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:41.080264 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.201s	user 0.151s	sys 0.050s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979621,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":346,"lbm_read_time_us":17407,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42138,"lbm_writes_lt_1ms":743,"mutex_wait_us":41,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":3500}
I20260812 06:16:41.080770 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:41.128784 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.048s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21619,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.129335 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:41.143409 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.143904 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:41.303251 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.159s	user 0.112s	sys 0.031s 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":856,"lbm_read_time_us":10510,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30137,"lbm_writes_lt_1ms":543,"mutex_wait_us":34,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:16:41.303925 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:41.362731 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.059s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":20464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.363195 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:41.373670 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.374293 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:41.549016 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.175s	user 0.130s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":716,"lbm_read_time_us":11860,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30083,"lbm_writes_lt_1ms":543,"mutex_wait_us":275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":123520,"update_count":2500}
I20260812 06:16:41.549644 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=14.095187
I20260812 06:16:41.610754 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.061s	user 0.037s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21532,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.611405 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:41.627502 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6095,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.628057 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8): perf score=1.000000
I20260812 06:16:41.796350 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: MajorDeltaCompactionOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.168s	user 0.113s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":159,"lbm_read_time_us":11606,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26992,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:16:41.797111 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=13.103000
I20260812 06:16:41.891165 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.094s	user 0.031s	sys 0.008s Metrics: {"bytes_written":15343277,"delete_count":0,"lbm_write_time_us":17736,"lbm_writes_lt_1ms":377,"reinsert_count":0,"update_count":1870}
I20260812 06:16:41.891711 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=5.165500
I20260812 06:16:42.004848 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.113s	user 0.008s	sys 0.009s Metrics: {"bytes_written":6482077,"delete_count":0,"lbm_write_time_us":7794,"lbm_writes_lt_1ms":161,"reinsert_count":0,"update_count":790}
I20260812 06:16:42.005908 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=9.134250
I20260812 06:16:42.048514 14986 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.726s	user 1.811s	sys 0.115s
I20260812 06:16:42.101598 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.095s	user 0.023s	sys 0.016s Metrics: {"bytes_written":10994718,"delete_count":0,"lbm_write_time_us":17724,"lbm_writes_lt_1ms":271,"reinsert_count":0,"update_count":1340}
I20260812 06:16:42.102231 15269 maintenance_manager.cc:419] P d3324622954546758318095617f1c7a7: Scheduling FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8): perf score=2.188937
I20260812 06:16:42.129293 14986 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.004s	sys 0.000s
I20260812 06:16:42.129923 14986 tablet_server.cc:179] TabletServer@127.14.162.129:0 shutting down...
I20260812 06:16:42.206590 15157 maintenance_manager.cc:643] P d3324622954546758318095617f1c7a7: FlushDeltaMemStoresOp(d08cb4824a55439a9aa6471da38597c8) complete. Timing: real 0.104s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.207311 14986 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:42.207784 14986 tablet_replica.cc:333] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7: stopping tablet replica
I20260812 06:16:42.208067 14986 raft_consensus.cc:2243] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.208338 14986 raft_consensus.cc:2272] T d08cb4824a55439a9aa6471da38597c8 P d3324622954546758318095617f1c7a7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.224754 14986 tablet_server.cc:196] TabletServer@127.14.162.129:0 shutdown complete.
I20260812 06:16:42.229679 14986 master.cc:562] Master@127.14.162.190:44905 shutting down...
I20260812 06:16:42.233719 14986 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:42.233880 14986 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:42.233939 14986 tablet_replica.cc:333] T 00000000000000000000000000000000 P 52752cbf091140ec964c39100c035f0e: stopping tablet replica
I20260812 06:16:42.246438 14986 master.cc:584] Master@127.14.162.190:44905 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5299 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:42.358515 14986 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.162.190:34069
I20260812 06:16:42.358944 14986 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.361038 15316 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:42.361420 15317 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:42.361476 15321 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:42.362164 14986 server_base.cc:1061] running on GCE node
I20260812 06:16:42.362371 14986 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.362430 14986 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:42.362454 14986 hybrid_clock.cc:648] HybridClock initialized: now 1786515402362453 us; error 0 us; skew 500 ppm
I20260812 06:16:42.363281 14986 webserver.cc:533] Webserver started at http://127.14.162.190:35499/ using document root <none> and password file <none>
I20260812 06:16:42.363466 14986 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.363550 14986 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.363631 14986 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.364017 14986 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/master-0-root/instance:
uuid: "8a2f7084c27d4136ba179e7b22c9577d"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-8hhm"
I20260812 06:16:42.365998 14986 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:42.366994 15329 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:42.367257 14986 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:42.367352 14986 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/master-0-root
uuid: "8a2f7084c27d4136ba179e7b22c9577d"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-8hhm"
I20260812 06:16:42.367444 14986 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-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:42.393865 14986 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.394335 14986 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.398453 14986 rpc_server.cc:307] RPC server started. Bound to: 127.14.162.190:34069
I20260812 06:16:42.399794 15412 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.162.190:34069 every 8 connection(s)
I20260812 06:16:42.399936 15413 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:42.415407 15413 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d: Bootstrap starting.
I20260812 06:16:42.416258 15413 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.417464 15413 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d: No bootstrap required, opened a new log
I20260812 06:16:42.417814 15413 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER }
I20260812 06:16:42.417902 15413 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.417924 15413 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8a2f7084c27d4136ba179e7b22c9577d, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.418038 15413 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [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: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER }
I20260812 06:16:42.418095 15413 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.418118 15413 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.418159 15413 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.512130 15413 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER }
I20260812 06:16:42.512418 15413 leader_election.cc:304] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [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: 8a2f7084c27d4136ba179e7b22c9577d; no voters: 
I20260812 06:16:42.512705 15413 leader_election.cc:290] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.512949 15422 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.513238 15422 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 1 LEADER]: Becoming Leader. State: Replica: 8a2f7084c27d4136ba179e7b22c9577d, State: Running, Role: LEADER
I20260812 06:16:42.513368 15413 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:42.513482 15422 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [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: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER }
I20260812 06:16:42.514079 15427 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8a2f7084c27d4136ba179e7b22c9577d. Latest consensus state: current_term: 1 leader_uuid: "8a2f7084c27d4136ba179e7b22c9577d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER } }
I20260812 06:16:42.514207 15427 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.514387 15424 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8a2f7084c27d4136ba179e7b22c9577d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8a2f7084c27d4136ba179e7b22c9577d" member_type: VOTER } }
I20260812 06:16:42.514497 15424 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:42.514537 15437 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:42.515518 15437 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:42.515728 14986 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:42.542897 15437 catalog_manager.cc:1383] Generated new cluster ID: 158bb1d0b30c4d9c9aa2c0433e501d0d
I20260812 06:16:42.543002 15437 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:42.557322 15437 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:42.558012 15437 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:42.575866 15437 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d: Generated new TSK 0
I20260812 06:16:42.576128 15437 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:42.580174 14986 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:42.582530 15461 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:42.582614 15459 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:42.582621 14986 server_base.cc:1061] running on GCE node
W20260812 06:16:42.582540 15454 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:42.583051 14986 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:42.583101 14986 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:42.583118 14986 hybrid_clock.cc:648] HybridClock initialized: now 1786515402583119 us; error 0 us; skew 500 ppm
I20260812 06:16:42.584055 14986 webserver.cc:533] Webserver started at http://127.14.162.129:40339/ using document root <none> and password file <none>
I20260812 06:16:42.584201 14986 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:42.584249 14986 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:42.584304 14986 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:42.584694 14986 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/instance:
uuid: "7038aafa303648ab8f33779e2bd918c1"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-8hhm"
I20260812 06:16:42.586373 14986 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:42.587332 15467 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:42.587589 14986 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:42.587658 14986 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root
uuid: "7038aafa303648ab8f33779e2bd918c1"
format_stamp: "Formatted at 2026-08-12 06:16:42 on dist-test-slave-8hhm"
I20260812 06:16:42.587716 14986 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-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:42.597688 14986 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:42.598008 14986 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:42.598266 14986 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:42.598748 14986 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:42.598786 14986 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.598855 14986 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:42.598899 14986 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:42.603449 14986 rpc_server.cc:307] RPC server started. Bound to: 127.14.162.129:33911
I20260812 06:16:42.603484 15569 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.162.129:33911 every 8 connection(s)
I20260812 06:16:42.613605 15570 heartbeater.cc:344] Connected to a master server at 127.14.162.190:34069
I20260812 06:16:42.613782 15570 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:42.614244 15570 heartbeater.cc:507] Master 127.14.162.190:34069 requested a full tablet report, sending...
I20260812 06:16:42.615061 15354 ts_manager.cc:194] Registered new tserver with Master: 7038aafa303648ab8f33779e2bd918c1 (127.14.162.129:33911)
I20260812 06:16:42.615299 14986 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011359347s
I20260812 06:16:42.616074 15354 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42946
I20260812 06:16:42.622825 15354 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42962:
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:42.631911 15513 tablet_service.cc:1511] Processing CreateTablet for tablet c52682468f1540d58ebd1948cabf48e7 (DEFAULT_TABLE table=heavy-update-compaction-test [id=22b99a9fb4aa49ba9d36b1e6f70b6049]), partition=
I20260812 06:16:42.632252 15513 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c52682468f1540d58ebd1948cabf48e7. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:42.634858 15586 tablet_bootstrap.cc:492] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Bootstrap starting.
I20260812 06:16:42.635756 15586 tablet_bootstrap.cc:654] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:42.636880 15586 tablet_bootstrap.cc:492] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: No bootstrap required, opened a new log
I20260812 06:16:42.637048 15586 ts_tablet_manager.cc:1403] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:42.637599 15586 raft_consensus.cc:359] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7038aafa303648ab8f33779e2bd918c1" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 33911 } }
I20260812 06:16:42.637705 15586 raft_consensus.cc:385] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:42.637735 15586 raft_consensus.cc:740] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7038aafa303648ab8f33779e2bd918c1, State: Initialized, Role: FOLLOWER
I20260812 06:16:42.637842 15586 consensus_queue.cc:260] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [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: "7038aafa303648ab8f33779e2bd918c1" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 33911 } }
I20260812 06:16:42.637904 15586 raft_consensus.cc:399] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:42.637928 15586 raft_consensus.cc:493] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:42.637965 15586 raft_consensus.cc:3060] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:42.647305 15586 raft_consensus.cc:515] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7038aafa303648ab8f33779e2bd918c1" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 33911 } }
I20260812 06:16:42.647488 15586 leader_election.cc:304] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [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: 7038aafa303648ab8f33779e2bd918c1; no voters: 
I20260812 06:16:42.647725 15586 leader_election.cc:290] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:42.647948 15588 raft_consensus.cc:2804] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:42.648099 15588 raft_consensus.cc:697] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 1 LEADER]: Becoming Leader. State: Replica: 7038aafa303648ab8f33779e2bd918c1, State: Running, Role: LEADER
I20260812 06:16:42.648164 15570 heartbeater.cc:499] Master 127.14.162.190:34069 was elected leader, sending a full tablet report...
I20260812 06:16:42.648104 15586 ts_tablet_manager.cc:1434] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Time spent starting tablet: real 0.011s	user 0.000s	sys 0.003s
I20260812 06:16:42.648301 15588 consensus_queue.cc:237] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [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: "7038aafa303648ab8f33779e2bd918c1" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 33911 } }
I20260812 06:16:42.649801 15354 catalog_manager.cc:5719] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7038aafa303648ab8f33779e2bd918c1 (127.14.162.129). New cstate: current_term: 1 leader_uuid: "7038aafa303648ab8f33779e2bd918c1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7038aafa303648ab8f33779e2bd918c1" member_type: VOTER last_known_addr { host: "127.14.162.129" port: 33911 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:42.715297 14986 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.016s	sys 0.008s
I20260812 06:16:42.854365 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushMRSOp(c52682468f1540d58ebd1948cabf48e7): perf score=19.054940
I20260812 06:16:43.058331 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushMRSOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.204s	user 0.111s	sys 0.050s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":84554,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41748,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:43.059051 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling LogGCOp(c52682468f1540d58ebd1948cabf48e7): free 20743880 bytes of WAL
I20260812 06:16:43.059304 15472 log_reader.cc:385] T c52682468f1540d58ebd1948cabf48e7: removed 2 log segments from log reader
I20260812 06:16:43.059350 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000001 (ops 1-6)
I20260812 06:16:43.059379 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000002 (ops 7-11)
I20260812 06:16:43.064502 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: LogGCOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:43.064905 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:43.153321 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.088s	user 0.023s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11833,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.153923 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:43.257854 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.104s	user 0.026s	sys 0.000s Metrics: {"bytes_written":8205077,"delete_count":0,"lbm_write_time_us":10743,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.258800 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7): 16411394 bytes on disk
I20260812 06:16:43.259344 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.259951 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=7.149875
I20260812 06:16:43.357676 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.098s	user 0.018s	sys 0.004s Metrics: {"bytes_written":8615322,"delete_count":0,"lbm_write_time_us":8733,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.358323 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=10.126437
I20260812 06:16:43.459332 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.101s	user 0.026s	sys 0.008s Metrics: {"bytes_written":11897251,"delete_count":0,"lbm_write_time_us":14319,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:43.459954 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:43.557341 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.097s	user 0.010s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8621,"lbm_writes_lt_1ms":203,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1000}
I20260812 06:16:43.557928 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=10.126437
I20260812 06:16:43.665380 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.107s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14216,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.666152 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:43.764703 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.098s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11257,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:43.765671 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=7.149875
I20260812 06:16:43.871758 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.106s	user 0.009s	sys 0.016s Metrics: {"bytes_written":8615324,"delete_count":0,"lbm_write_time_us":11659,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:43.872454 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=10.126437
I20260812 06:16:43.977181 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.105s	user 0.020s	sys 0.012s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":14188,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:43.977886 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=7.149875
I20260812 06:16:44.074679 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.097s	user 0.009s	sys 0.013s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9807,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:44.075230 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:44.174822 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.099s	user 0.011s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8420,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.175359 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=10.126437
I20260812 06:16:44.275064 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.100s	user 0.015s	sys 0.020s Metrics: {"bytes_written":11897249,"delete_count":0,"lbm_write_time_us":15262,"lbm_writes_lt_1ms":293,"reinsert_count":0,"update_count":1450}
I20260812 06:16:44.275920 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=6.157687
I20260812 06:16:44.375581 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.099s	user 0.015s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9808,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:44.376091 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=7.149875
I20260812 06:16:44.395713 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.019s	user 0.014s	sys 0.003s Metrics: {"bytes_written":8615327,"delete_count":0,"lbm_write_time_us":8281,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:44.396240 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=2.188937
I20260812 06:16:44.427428 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.031s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4969,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.428097 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=2.188937
I20260812 06:16:44.440271 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.440829 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushMRSOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.000000
I20260812 06:16:44.480439 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushMRSOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.039s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1521476,"cfile_init":1,"dirs.queue_time_us":235,"dirs.run_cpu_time_us":303,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1683,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":37,"thread_start_us":104,"threads_started":1}
I20260812 06:16:44.481150 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling LogGCOp(c52682468f1540d58ebd1948cabf48e7): free 153809421 bytes of WAL
I20260812 06:16:44.481442 15472 log_reader.cc:385] T c52682468f1540d58ebd1948cabf48e7: removed 15 log segments from log reader
I20260812 06:16:44.481520 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000003 (ops 12-16)
I20260812 06:16:44.481559 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000004 (ops 17-20)
I20260812 06:16:44.481587 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000005 (ops 21-25)
I20260812 06:16:44.481621 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000006 (ops 26-30)
I20260812 06:16:44.481644 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000007 (ops 31-35)
I20260812 06:16:44.481667 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000008 (ops 36-40)
I20260812 06:16:44.481695 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000009 (ops 41-45)
I20260812 06:16:44.481725 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000010 (ops 46-50)
I20260812 06:16:44.481760 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000011 (ops 51-55)
I20260812 06:16:44.481789 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000012 (ops 56-60)
I20260812 06:16:44.481812 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000013 (ops 61-65)
I20260812 06:16:44.481841 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000014 (ops 66-70)
I20260812 06:16:44.481866 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000015 (ops 71-75)
I20260812 06:16:44.481897 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000016 (ops 76-80)
I20260812 06:16:44.481930 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000017 (ops 81-85)
I20260812 06:16:44.519593 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: LogGCOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.038s	user 0.000s	sys 0.036s Metrics: {}
I20260812 06:16:44.520061 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=2.188937
I20260812 06:16:44.544070 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.024s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.544543 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7): 555 bytes on disk
I20260812 06:16:44.544924 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:44.545387 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=2.188937
I20260812 06:16:44.555423 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.555837 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling MajorDeltaCompactionOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.000000
I20260812 06:16:46.210827 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: MajorDeltaCompactionOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 1.655s	user 0.754s	sys 0.897s Metrics: {"cfile_cache_miss":3949,"cfile_cache_miss_bytes":164258741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":19,"delta_iterators_relevant":19,"dirs.queue_time_us":1418,"lbm_read_time_us":70556,"lbm_reads_lt_1ms":3985,"lbm_write_time_us":563862,"lbm_writes_1-10_ms":6,"lbm_writes_lt_1ms":3940,"peak_mem_usage":485619348,"reinsert_count":0,"spinlock_wait_cycles":45440,"thread_start_us":646,"threads_started":7,"update_count":19500}
I20260812 06:16:46.211807 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=81.563937
I20260812 06:16:46.637836 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.426s	user 0.163s	sys 0.095s Metrics: {"bytes_written":86151035,"delete_count":0,"lbm_write_time_us":116532,"lbm_writes_lt_1ms":2105,"reinsert_count":0,"update_count":10500}
I20260812 06:16:46.638482 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=29.970187
I20260812 06:16:46.730681 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.092s	user 0.054s	sys 0.034s Metrics: {"bytes_written":32819552,"delete_count":0,"lbm_write_time_us":42540,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":801,"reinsert_count":0,"update_count":4000}
I20260812 06:16:46.731390 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=3.181125
I20260812 06:16:46.783215 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.052s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4882125,"delete_count":0,"lbm_write_time_us":7240,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:16:46.784413 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=5.165500
I20260812 06:16:46.815893 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.031s	user 0.016s	sys 0.008s Metrics: {"bytes_written":6605144,"delete_count":0,"lbm_write_time_us":10704,"lbm_writes_lt_1ms":164,"reinsert_count":0,"update_count":805}
I20260812 06:16:46.816449 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.000000
I20260812 06:16:46.833554 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.017s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1230906,"delete_count":0,"lbm_write_time_us":1482,"lbm_writes_lt_1ms":33,"reinsert_count":0,"update_count":150}
I20260812 06:16:46.834124 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=2.188937
I20260812 06:16:46.843883 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3823,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:46.844441 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushMRSOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.000000
I20260812 06:16:46.882835 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushMRSOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.038s	user 0.033s	sys 0.004s Metrics: {"bytes_written":1439520,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1595,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1859,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":35}
I20260812 06:16:46.883745 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling LogGCOp(c52682468f1540d58ebd1948cabf48e7): free 141791617 bytes of WAL
I20260812 06:16:46.883982 15472 log_reader.cc:385] T c52682468f1540d58ebd1948cabf48e7: removed 14 log segments from log reader
I20260812 06:16:46.884045 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000018 (ops 86-90)
I20260812 06:16:46.884135 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000019 (ops 91-95)
I20260812 06:16:46.884176 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000020 (ops 96-100)
I20260812 06:16:46.884199 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000021 (ops 101-105)
I20260812 06:16:46.884222 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000022 (ops 106-110)
I20260812 06:16:46.884253 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000023 (ops 111-115)
I20260812 06:16:46.884285 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000024 (ops 116-120)
I20260812 06:16:46.884310 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000025 (ops 121-125)
I20260812 06:16:46.884336 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000026 (ops 126-130)
I20260812 06:16:46.884362 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000027 (ops 131-135)
I20260812 06:16:46.884383 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000028 (ops 136-140)
I20260812 06:16:46.884407 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000029 (ops 141-144)
I20260812 06:16:46.884445 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000030 (ops 145-149)
I20260812 06:16:46.884470 15472 log.cc:1079] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: Deleting log segment in path: /tmp/dist-test-taskjn4r7F/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515397048787-14986-0/minicluster-data/ts-0-root/wals/c52682468f1540d58ebd1948cabf48e7/wal-000000031 (ops 150-154)
I20260812 06:16:46.919471 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: LogGCOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.036s	user 0.003s	sys 0.030s Metrics: {}
I20260812 06:16:46.919857 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=4.173312
I20260812 06:16:46.933204 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.013s	user 0.004s	sys 0.008s Metrics: {"bytes_written":5333392,"delete_count":0,"lbm_write_time_us":5710,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:16:46.933893 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7): 528 bytes on disk
I20260812 06:16:46.934267 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: UndoDeltaBlockGCOp(c52682468f1540d58ebd1948cabf48e7) 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:46.934707 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.196750
I20260812 06:16:46.945514 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:16:46.954340 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling MajorDeltaCompactionOp(c52682468f1540d58ebd1948cabf48e7): perf score=1.000000
I20260812 06:16:47.977794 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: MajorDeltaCompactionOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 1.023s	user 0.566s	sys 0.456s Metrics: {"cfile_cache_miss":3540,"cfile_cache_miss_bytes":147847808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":8,"delta_iterators_relevant":8,"dirs.queue_time_us":437,"lbm_read_time_us":67914,"lbm_reads_lt_1ms":3580,"lbm_write_time_us":224934,"lbm_writes_1-10_ms":7,"lbm_writes_lt_1ms":3539,"peak_mem_usage":435913060,"reinsert_count":0,"spinlock_wait_cycles":37632,"thread_start_us":928,"threads_started":7,"update_count":17500}
I20260812 06:16:47.978519 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=65.688937
I20260812 06:16:48.288942 14986 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.574s	user 1.762s	sys 0.210s
I20260812 06:16:48.325793 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.347s	user 0.096s	sys 0.170s Metrics: {"bytes_written":69741385,"delete_count":0,"lbm_write_time_us":168030,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":1704,"reinsert_count":0,"update_count":8500}
I20260812 06:16:48.326681 15572 maintenance_manager.cc:419] P 7038aafa303648ab8f33779e2bd918c1: Scheduling FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7): perf score=18.063937
I20260812 06:16:48.410624 14986 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.121s	user 0.002s	sys 0.000s
I20260812 06:16:48.411258 14986 tablet_server.cc:179] TabletServer@127.14.162.129:0 shutting down...
I20260812 06:16:48.454109 15472 maintenance_manager.cc:643] P 7038aafa303648ab8f33779e2bd918c1: FlushDeltaMemStoresOp(c52682468f1540d58ebd1948cabf48e7) complete. Timing: real 0.127s	user 0.072s	sys 0.054s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":88378,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:48.454766 14986 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:48.455034 14986 tablet_replica.cc:333] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1: stopping tablet replica
I20260812 06:16:48.455212 14986 raft_consensus.cc:2243] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.470896 14986 raft_consensus.cc:2272] T c52682468f1540d58ebd1948cabf48e7 P 7038aafa303648ab8f33779e2bd918c1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.475257 14986 tablet_server.cc:196] TabletServer@127.14.162.129:0 shutdown complete.
I20260812 06:16:48.510177 14986 master.cc:562] Master@127.14.162.190:34069 shutting down...
I20260812 06:16:48.513536 14986 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.513711 14986 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.513762 14986 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8a2f7084c27d4136ba179e7b22c9577d: stopping tablet replica
I20260812 06:16:48.526129 14986 master.cc:584] Master@127.14.162.190:34069 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (6271 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11571 ms total)

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