[==========] 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:32.974143 10678 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.109.190:41589
I20260812 06:16:32.975198 10678 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:32.975813 10678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:32.982625 10684 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:32.982719 10678 server_base.cc:1061] running on GCE node
W20260812 06:16:32.982625 10683 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:32.982909 10688 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:32.983436 10678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:32.983575 10678 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:32.983625 10678 hybrid_clock.cc:648] HybridClock initialized: now 1786515392983622 us; error 0 us; skew 500 ppm
I20260812 06:16:32.985460 10678 webserver.cc:533] Webserver started at http://127.10.109.190:44383/ using document root <none> and password file <none>
I20260812 06:16:32.986024 10678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:32.986088 10678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:32.986331 10678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:32.988124 10678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/master-0-root/instance:
uuid: "122124dd69aa4ecdbfe2914ef5db3e70"
format_stamp: "Formatted at 2026-08-12 06:16:32 on dist-test-slave-bt4h"
I20260812 06:16:32.991812 10678 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:32.994012 10693 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:32.995190 10678 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:32.995339 10678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/master-0-root
uuid: "122124dd69aa4ecdbfe2914ef5db3e70"
format_stamp: "Formatted at 2026-08-12 06:16:32 on dist-test-slave-bt4h"
I20260812 06:16:32.995452 10678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-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:33.017728 10678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:33.018473 10678 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:33.018700 10678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:33.027127 10678 rpc_server.cc:307] RPC server started. Bound to: 127.10.109.190:41589
I20260812 06:16:33.027143 10750 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.109.190:41589 every 8 connection(s)
I20260812 06:16:33.029599 10752 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:33.035238 10752 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: Bootstrap starting.
I20260812 06:16:33.037747 10752 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:33.038789 10752 log.cc:826] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:33.040750 10752 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: No bootstrap required, opened a new log
I20260812 06:16:33.043769 10752 raft_consensus.cc:359] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER }
I20260812 06:16:33.043956 10752 raft_consensus.cc:385] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:33.044075 10752 raft_consensus.cc:740] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 122124dd69aa4ecdbfe2914ef5db3e70, State: Initialized, Role: FOLLOWER
I20260812 06:16:33.044811 10752 consensus_queue.cc:260] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [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: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER }
I20260812 06:16:33.045001 10752 raft_consensus.cc:399] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:33.045075 10752 raft_consensus.cc:493] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:33.045252 10752 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:33.046155 10752 raft_consensus.cc:515] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER }
I20260812 06:16:33.046669 10752 leader_election.cc:304] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [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: 122124dd69aa4ecdbfe2914ef5db3e70; no voters: 
I20260812 06:16:33.047072 10752 leader_election.cc:290] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:33.047223 10756 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:33.047502 10756 raft_consensus.cc:697] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 1 LEADER]: Becoming Leader. State: Replica: 122124dd69aa4ecdbfe2914ef5db3e70, State: Running, Role: LEADER
I20260812 06:16:33.047950 10756 consensus_queue.cc:237] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [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: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER }
I20260812 06:16:33.048261 10752 sys_catalog.cc:565] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:33.050030 10758 sys_catalog.cc:455] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 122124dd69aa4ecdbfe2914ef5db3e70. Latest consensus state: current_term: 1 leader_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER } }
I20260812 06:16:33.050091 10757 sys_catalog.cc:455] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "122124dd69aa4ecdbfe2914ef5db3e70" member_type: VOTER } }
I20260812 06:16:33.050215 10757 sys_catalog.cc:458] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:33.050163 10758 sys_catalog.cc:458] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:33.050882 10678 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:33.050894 10772 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:33.053208 10772 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:33.058137 10772 catalog_manager.cc:1383] Generated new cluster ID: 71b754c2031d4234aa912df3306cc1d6
I20260812 06:16:33.058211 10772 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:33.077917 10772 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:33.079411 10772 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:33.086033 10772 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: Generated new TSK 0
I20260812 06:16:33.086891 10772 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:33.115763 10678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:33.118700 10779 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:33.118736 10781 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:33.118736 10778 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:33.119295 10678 server_base.cc:1061] running on GCE node
I20260812 06:16:33.119486 10678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:33.119539 10678 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:33.119556 10678 hybrid_clock.cc:648] HybridClock initialized: now 1786515393119556 us; error 0 us; skew 500 ppm
I20260812 06:16:33.120599 10678 webserver.cc:533] Webserver started at http://127.10.109.129:45245/ using document root <none> and password file <none>
I20260812 06:16:33.120811 10678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:33.120859 10678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:33.120960 10678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:33.121381 10678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/instance:
uuid: "9319aa3586244358ad09e5519249432f"
format_stamp: "Formatted at 2026-08-12 06:16:33 on dist-test-slave-bt4h"
I20260812 06:16:33.123042 10678 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:33.124086 10786 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:33.124353 10678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:33.124431 10678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root
uuid: "9319aa3586244358ad09e5519249432f"
format_stamp: "Formatted at 2026-08-12 06:16:33 on dist-test-slave-bt4h"
I20260812 06:16:33.124526 10678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-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:33.139966 10678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:33.140491 10678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:33.141049 10678 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:33.141973 10678 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:33.142030 10678 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:33.142099 10678 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:33.142138 10678 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:33.149533 10678 rpc_server.cc:307] RPC server started. Bound to: 127.10.109.129:35393
I20260812 06:16:33.149596 10862 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.109.129:35393 every 8 connection(s)
I20260812 06:16:33.160223 10863 heartbeater.cc:344] Connected to a master server at 127.10.109.190:41589
I20260812 06:16:33.160590 10863 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:33.161067 10863 heartbeater.cc:507] Master 127.10.109.190:41589 requested a full tablet report, sending...
I20260812 06:16:33.162675 10711 ts_manager.cc:194] Registered new tserver with Master: 9319aa3586244358ad09e5519249432f (127.10.109.129:35393)
I20260812 06:16:33.162757 10678 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012489094s
I20260812 06:16:33.164182 10711 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42084
I20260812 06:16:33.172400 10711 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42096:
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:33.186419 10821 tablet_service.cc:1511] Processing CreateTablet for tablet 104359d073bc4c64918c7729f6812b96 (DEFAULT_TABLE table=heavy-update-compaction-test [id=d630b3c9f5b145e0aa2b9a6a5403bccb]), partition=
I20260812 06:16:33.186995 10821 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 104359d073bc4c64918c7729f6812b96. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:33.190172 10879 tablet_bootstrap.cc:492] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Bootstrap starting.
I20260812 06:16:33.192071 10879 tablet_bootstrap.cc:654] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:33.193809 10879 tablet_bootstrap.cc:492] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: No bootstrap required, opened a new log
I20260812 06:16:33.193964 10879 ts_tablet_manager.cc:1403] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Time spent bootstrapping tablet: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:16:33.194808 10879 raft_consensus.cc:359] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9319aa3586244358ad09e5519249432f" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 35393 } }
I20260812 06:16:33.195009 10879 raft_consensus.cc:385] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:33.195135 10879 raft_consensus.cc:740] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9319aa3586244358ad09e5519249432f, State: Initialized, Role: FOLLOWER
I20260812 06:16:33.195509 10879 consensus_queue.cc:260] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [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: "9319aa3586244358ad09e5519249432f" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 35393 } }
I20260812 06:16:33.195658 10879 raft_consensus.cc:399] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:33.195715 10879 raft_consensus.cc:493] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:33.195775 10879 raft_consensus.cc:3060] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:33.196970 10879 raft_consensus.cc:515] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9319aa3586244358ad09e5519249432f" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 35393 } }
I20260812 06:16:33.197131 10879 leader_election.cc:304] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [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: 9319aa3586244358ad09e5519249432f; no voters: 
I20260812 06:16:33.197388 10879 leader_election.cc:290] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:33.197491 10882 raft_consensus.cc:2804] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:33.197670 10882 raft_consensus.cc:697] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 1 LEADER]: Becoming Leader. State: Replica: 9319aa3586244358ad09e5519249432f, State: Running, Role: LEADER
I20260812 06:16:33.197759 10879 ts_tablet_manager.cc:1434] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Time spent starting tablet: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:16:33.197819 10882 consensus_queue.cc:237] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [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: "9319aa3586244358ad09e5519249432f" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 35393 } }
I20260812 06:16:33.198189 10863 heartbeater.cc:499] Master 127.10.109.190:41589 was elected leader, sending a full tablet report...
I20260812 06:16:33.201521 10710 catalog_manager.cc:5719] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f reported cstate change: term changed from 0 to 1, leader changed from <none> to 9319aa3586244358ad09e5519249432f (127.10.109.129). New cstate: current_term: 1 leader_uuid: "9319aa3586244358ad09e5519249432f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9319aa3586244358ad09e5519249432f" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 35393 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:33.311550 10678 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.102s	user 0.017s	sys 0.024s
I20260812 06:16:33.400764 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushMRSOp(104359d073bc4c64918c7729f6812b96): perf score=10.125253
I20260812 06:16:33.549259 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushMRSOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.148s	user 0.100s	sys 0.048s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1295,"drs_written":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36601,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":102,"thread_start_us":132,"threads_started":1,"update_count":1500}
I20260812 06:16:33.550514 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling LogGCOp(104359d073bc4c64918c7729f6812b96): free 8725963 bytes of WAL
I20260812 06:16:33.550972 10794 log_reader.cc:385] T 104359d073bc4c64918c7729f6812b96: removed 1 log segments from log reader
I20260812 06:16:33.551041 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000001 (ops 1-6)
I20260812 06:16:33.553349 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: LogGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:16:33.553699 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:33.573969 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.020s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.574620 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:33.719658 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.145s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1694,"lbm_read_time_us":7800,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30132,"lbm_writes_lt_1ms":443,"mutex_wait_us":339,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":356,"threads_started":5,"update_count":2000}
I20260812 06:16:33.720460 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:33.761472 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.041s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18492,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":67328,"update_count":1500}
I20260812 06:16:33.761951 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:33.774362 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4336,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.774868 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96): 8206537 bytes on disk
I20260812 06:16:33.775353 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96) 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:33.775753 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:33.899782 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.124s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590347,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":727,"lbm_read_time_us":9120,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23632,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2000}
I20260812 06:16:33.900473 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:33.945390 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.045s	user 0.031s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15931,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:33.945992 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:33.957051 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.957628 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:34.112089 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.154s	user 0.097s	sys 0.057s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":632,"lbm_read_time_us":10321,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27476,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:16:34.112663 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:34.156668 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.044s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16074,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:34.157111 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:34.168076 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.168651 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:34.305909 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.137s	user 0.117s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":984,"lbm_read_time_us":9477,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29781,"lbm_writes_lt_1ms":443,"mutex_wait_us":267,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:16:34.306696 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:34.348626 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.042s	user 0.026s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20411,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:34.349166 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:34.361785 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.362248 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:34.486476 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.124s	user 0.108s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":924,"lbm_read_time_us":9080,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24533,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:16:34.487222 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:34.527436 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17097,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:34.527925 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:34.538514 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.539028 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:34.670130 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.131s	user 0.113s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":52,"lbm_read_time_us":9372,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26865,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:16:34.673761 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:34.717006 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.043s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16369,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:34.717722 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:34.728681 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4127,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.729359 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushMRSOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:34.757511 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushMRSOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.028s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1481,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1600,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:34.758335 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling LogGCOp(104359d073bc4c64918c7729f6812b96): free 115943169 bytes of WAL
I20260812 06:16:34.758630 10794 log_reader.cc:385] T 104359d073bc4c64918c7729f6812b96: removed 11 log segments from log reader
I20260812 06:16:34.758678 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000002 (ops 7-11)
I20260812 06:16:34.758710 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000003 (ops 12-16)
I20260812 06:16:34.758780 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000004 (ops 17-21)
I20260812 06:16:34.758827 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000005 (ops 22-26)
I20260812 06:16:34.758870 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000006 (ops 27-31)
I20260812 06:16:34.758908 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000007 (ops 32-36)
I20260812 06:16:34.758944 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000008 (ops 37-41)
I20260812 06:16:34.758983 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000009 (ops 42-46)
I20260812 06:16:34.759017 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000010 (ops 47-51)
I20260812 06:16:34.759055 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000011 (ops 52-56)
I20260812 06:16:34.759093 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000012 (ops 57-61)
I20260812 06:16:34.785466 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: LogGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.027s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:16:34.786085 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=3.181125
I20260812 06:16:34.799609 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4433,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:34.800112 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:34.813887 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5502,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:34.814404 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:35.009451 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.195s	user 0.148s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28795391,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1559,"lbm_read_time_us":12447,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33569,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:16:35.010411 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=14.095187
I20260812 06:16:35.066504 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.056s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":19914,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:35.067082 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:35.083161 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.083772 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96): 447 bytes on disk
I20260812 06:16:35.084473 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":95,"lbm_reads_lt_1ms":4}
I20260812 06:16:35.085004 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:35.254792 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.170s	user 0.108s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692763,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":10898,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28510,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:35.260632 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=14.095187
I20260812 06:16:35.323668 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.063s	user 0.035s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27932,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:35.324188 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:35.335161 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4234,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.335651 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:35.514691 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.179s	user 0.134s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692758,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":844,"lbm_read_time_us":13485,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31627,"lbm_writes_lt_1ms":543,"mutex_wait_us":76,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:16:35.515287 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:35.546175 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.031s	user 0.010s	sys 0.017s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13734,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:35.546842 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:35.567278 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5155,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:35.567868 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:35.729190 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.161s	user 0.113s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590340,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":250,"lbm_read_time_us":9755,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28123,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:16:35.729878 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:35.767603 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.037s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.768180 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:35.787165 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.019s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.787774 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:35.925324 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.137s	user 0.108s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":9202,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28606,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:35.926240 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:35.969924 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.043s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20549,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.970444 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:35.983052 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4808,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.983626 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.119423 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.136s	user 0.109s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1740,"lbm_read_time_us":8903,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29035,"lbm_writes_lt_1ms":443,"mutex_wait_us":429,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:16:36.120221 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=10.126437
I20260812 06:16:36.163697 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.043s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.164402 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:36.174990 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.175450 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushMRSOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.207680 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushMRSOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.032s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":271,"dirs.run_wall_time_us":1388,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1356,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:36.208480 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96): 448 bytes on disk
I20260812 06:16:36.208978 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:16:36.209527 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.363379 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.154s	user 0.092s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590346,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1397,"lbm_read_time_us":10458,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25151,"lbm_writes_lt_1ms":443,"mutex_wait_us":883,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2000}
I20260812 06:16:36.364073 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling LogGCOp(104359d073bc4c64918c7729f6812b96): free 120553382 bytes of WAL
I20260812 06:16:36.364439 10794 log_reader.cc:385] T 104359d073bc4c64918c7729f6812b96: removed 12 log segments from log reader
I20260812 06:16:36.364508 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000013 (ops 62-66)
I20260812 06:16:36.364557 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000014 (ops 67-70)
I20260812 06:16:36.364599 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000015 (ops 71-75)
I20260812 06:16:36.364650 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000016 (ops 76-80)
I20260812 06:16:36.364692 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000017 (ops 81-85)
I20260812 06:16:36.364733 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000018 (ops 86-90)
I20260812 06:16:36.364776 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000019 (ops 91-95)
I20260812 06:16:36.364818 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000020 (ops 96-100)
I20260812 06:16:36.364861 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000021 (ops 101-104)
I20260812 06:16:36.364903 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000022 (ops 105-109)
I20260812 06:16:36.364946 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000023 (ops 110-114)
I20260812 06:16:36.364988 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000024 (ops 115-119)
I20260812 06:16:36.388844 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: LogGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:36.389285 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=14.095187
I20260812 06:16:36.434583 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.045s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20334,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:36.435124 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:36.452222 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.017s	user 0.002s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.452703 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.606977 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.154s	user 0.121s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":352,"lbm_read_time_us":9181,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31976,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:16:36.608260 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:36.644886 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.036s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16218,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:36.646100 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:36.662510 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6677,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:36.663266 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.788745 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.125s	user 0.091s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590339,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1102,"lbm_read_time_us":7090,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25167,"lbm_writes_lt_1ms":443,"mutex_wait_us":236,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":2000}
I20260812 06:16:36.789417 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:36.824498 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.035s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15609,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:16:36.825145 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:36.837411 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:36.837875 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:36.977456 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.139s	user 0.093s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590338,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":515,"lbm_read_time_us":7801,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26410,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22656,"update_count":2000}
I20260812 06:16:36.978101 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:37.024600 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.046s	user 0.025s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16774,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:37.025314 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:37.039657 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.040271 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:37.199201 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.159s	user 0.117s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20590339,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":10653,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27238,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:16:37.200018 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:37.234058 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.034s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14935,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:37.235189 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:37.260923 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.026s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.261524 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:37.272444 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.273171 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:37.485245 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.212s	user 0.138s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24692869,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":733,"lbm_read_time_us":10111,"lbm_reads_lt_1ms":573,"lbm_write_time_us":58057,"lbm_writes_1-10_ms":8,"lbm_writes_lt_1ms":535,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:37.486111 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=11.118625
I20260812 06:16:37.576840 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.091s	user 0.029s	sys 0.052s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":56991,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:37.577401 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=6.157687
I20260812 06:16:37.628041 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.050s	user 0.020s	sys 0.025s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":29874,"lbm_writes_lt_1ms":193,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":950}
I20260812 06:16:37.628604 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:37.639353 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4095,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.640061 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushMRSOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:37.676906 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushMRSOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.037s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1152511,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1372,"drs_written":1,"lbm_read_time_us":142,"lbm_reads_lt_1ms":4,"lbm_write_time_us":3512,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":38,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:37.677923 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling LogGCOp(104359d073bc4c64918c7729f6812b96): free 112239512 bytes of WAL
I20260812 06:16:37.678212 10794 log_reader.cc:385] T 104359d073bc4c64918c7729f6812b96: removed 11 log segments from log reader
I20260812 06:16:37.678277 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000025 (ops 120-124)
I20260812 06:16:37.678383 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000026 (ops 125-129)
I20260812 06:16:37.678431 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000027 (ops 130-134)
I20260812 06:16:37.678503 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000028 (ops 135-139)
I20260812 06:16:37.678568 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000029 (ops 140-144)
I20260812 06:16:37.678637 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000030 (ops 145-149)
I20260812 06:16:37.678676 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000031 (ops 150-154)
I20260812 06:16:37.678721 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000032 (ops 155-159)
I20260812 06:16:37.678762 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000033 (ops 160-164)
I20260812 06:16:37.678799 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000034 (ops 165-168)
I20260812 06:16:37.678830 10794 log.cc:1079] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/104359d073bc4c64918c7729f6812b96/wal-000000035 (ops 169-173)
I20260812 06:16:37.703255 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: LogGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.025s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:16:37.703642 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96): 447 bytes on disk
I20260812 06:16:37.704039 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: UndoDeltaBlockGCOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:37.704535 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=3.181125
I20260812 06:16:37.729575 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.025s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:37.730065 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:37.740691 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.741415 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:37.998373 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.257s	user 0.128s	sys 0.128s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37000345,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":866,"lbm_read_time_us":18803,"lbm_reads_lt_1ms":875,"lbm_write_time_us":45440,"lbm_writes_lt_1ms":843,"mutex_wait_us":23,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":21632,"thread_start_us":306,"threads_started":5,"update_count":4000}
I20260812 06:16:37.999249 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=18.063937
I20260812 06:16:38.069077 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.070s	user 0.023s	sys 0.031s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25676,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:38.069650 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:38.080616 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.081180 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:38.285355 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.204s	user 0.119s	sys 0.082s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28795172,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":13183,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34345,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":29440,"update_count":3000}
I20260812 06:16:38.286080 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=14.095187
I20260812 06:16:38.354080 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.068s	user 0.026s	sys 0.035s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30630,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.354696 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96): perf score=2.188937
I20260812 06:16:38.365612 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: FlushDeltaMemStoresOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4163,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.366091 10864 maintenance_manager.cc:419] P 9319aa3586244358ad09e5519249432f: Scheduling MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96): perf score=1.000000
I20260812 06:16:38.404807 10678 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.093s	user 1.864s	sys 0.136s
I20260812 06:16:38.470307 10678 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.001s	sys 0.000s
I20260812 06:16:38.471033 10678 tablet_server.cc:179] TabletServer@127.10.109.129:0 shutting down...
I20260812 06:16:38.555744 10794 maintenance_manager.cc:643] P 9319aa3586244358ad09e5519249432f: MajorDeltaCompactionOp(104359d073bc4c64918c7729f6812b96) complete. Timing: real 0.189s	user 0.092s	sys 0.095s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24692759,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":161,"lbm_read_time_us":13390,"lbm_reads_lt_1ms":568,"lbm_write_time_us":52462,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":541,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:16:38.556679 10678 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:38.557144 10678 tablet_replica.cc:333] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f: stopping tablet replica
I20260812 06:16:38.557405 10678 raft_consensus.cc:2243] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:38.557657 10678 raft_consensus.cc:2272] T 104359d073bc4c64918c7729f6812b96 P 9319aa3586244358ad09e5519249432f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:38.575048 10678 tablet_server.cc:196] TabletServer@127.10.109.129:0 shutdown complete.
I20260812 06:16:38.602967 10678 master.cc:562] Master@127.10.109.190:41589 shutting down...
I20260812 06:16:38.607055 10678 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:38.607234 10678 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:38.607290 10678 tablet_replica.cc:333] T 00000000000000000000000000000000 P 122124dd69aa4ecdbfe2914ef5db3e70: stopping tablet replica
I20260812 06:16:38.619719 10678 master.cc:584] Master@127.10.109.190:41589 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5737 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:38.724627 10678 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.109.190:45073
I20260812 06:16:38.725093 10678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.727336 10912 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:38.727394 10915 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:38.727411 10911 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:38.727445 10678 server_base.cc:1061] running on GCE node
I20260812 06:16:38.727918 10678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.727978 10678 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:38.727995 10678 hybrid_clock.cc:648] HybridClock initialized: now 1786515398727995 us; error 0 us; skew 500 ppm
I20260812 06:16:38.728907 10678 webserver.cc:533] Webserver started at http://127.10.109.190:36527/ using document root <none> and password file <none>
I20260812 06:16:38.729094 10678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.729166 10678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.729238 10678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.729641 10678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/master-0-root/instance:
uuid: "6a12060d754a45c7a352337c3ab596eb"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-bt4h"
I20260812 06:16:38.731515 10678 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.732613 10920 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:38.732873 10678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:38.732967 10678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/master-0-root
uuid: "6a12060d754a45c7a352337c3ab596eb"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-bt4h"
I20260812 06:16:38.733055 10678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-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:38.742118 10678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.742620 10678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.747390 10678 rpc_server.cc:307] RPC server started. Bound to: 127.10.109.190:45073
I20260812 06:16:38.752399 10984 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.109.190:45073 every 8 connection(s)
I20260812 06:16:38.752916 10985 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:38.754956 10985 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb: Bootstrap starting.
I20260812 06:16:38.755822 10985 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.756961 10985 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb: No bootstrap required, opened a new log
I20260812 06:16:38.757426 10985 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER }
I20260812 06:16:38.757544 10985 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.757606 10985 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6a12060d754a45c7a352337c3ab596eb, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.757791 10985 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [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: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER }
I20260812 06:16:38.757889 10985 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.757933 10985 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.757989 10985 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.758832 10985 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER }
I20260812 06:16:38.759001 10985 leader_election.cc:304] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [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: 6a12060d754a45c7a352337c3ab596eb; no voters: 
I20260812 06:16:38.759220 10985 leader_election.cc:290] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.759459 10991 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.759701 10991 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 1 LEADER]: Becoming Leader. State: Replica: 6a12060d754a45c7a352337c3ab596eb, State: Running, Role: LEADER
I20260812 06:16:38.759755 10985 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:38.759918 10991 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [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: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER }
I20260812 06:16:38.760460 10993 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6a12060d754a45c7a352337c3ab596eb. Latest consensus state: current_term: 1 leader_uuid: "6a12060d754a45c7a352337c3ab596eb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER } }
I20260812 06:16:38.760547 10993 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.760720 10992 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6a12060d754a45c7a352337c3ab596eb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6a12060d754a45c7a352337c3ab596eb" member_type: VOTER } }
I20260812 06:16:38.760834 10992 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.761252 10997 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:38.761952 10997 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:38.762198 10678 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:38.763926 10997 catalog_manager.cc:1383] Generated new cluster ID: 9876b256302b4d87990650f071950bdb
I20260812 06:16:38.763988 10997 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:38.787729 10997 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:38.788386 10997 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:38.795624 10997 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb: Generated new TSK 0
I20260812 06:16:38.795872 10997 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:38.827165 10678 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.829406 11010 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:38.829421 11013 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:38.829422 11011 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:38.829766 10678 server_base.cc:1061] running on GCE node
I20260812 06:16:38.829896 10678 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.829931 10678 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:38.829945 10678 hybrid_clock.cc:648] HybridClock initialized: now 1786515398829946 us; error 0 us; skew 500 ppm
I20260812 06:16:38.830842 10678 webserver.cc:533] Webserver started at http://127.10.109.129:33581/ using document root <none> and password file <none>
I20260812 06:16:38.830983 10678 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.831027 10678 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.831079 10678 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.831442 10678 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/instance:
uuid: "0196ea1d6ad141bea6dd78baad6409d9"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-bt4h"
I20260812 06:16:38.832973 10678 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:38.834018 11022 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:38.834376 10678 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:38.834472 10678 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root
uuid: "0196ea1d6ad141bea6dd78baad6409d9"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-bt4h"
I20260812 06:16:38.834607 10678 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-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:38.844692 10678 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.845165 10678 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.845513 10678 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:38.846014 10678 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:38.846076 10678 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.846135 10678 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:38.846184 10678 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.850903 10678 rpc_server.cc:307] RPC server started. Bound to: 127.10.109.129:32829
I20260812 06:16:38.850926 11096 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.109.129:32829 every 8 connection(s)
I20260812 06:16:38.865598 11097 heartbeater.cc:344] Connected to a master server at 127.10.109.190:45073
I20260812 06:16:38.865734 11097 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:38.865968 11097 heartbeater.cc:507] Master 127.10.109.190:45073 requested a full tablet report, sending...
I20260812 06:16:38.866849 10942 ts_manager.cc:194] Registered new tserver with Master: 0196ea1d6ad141bea6dd78baad6409d9 (127.10.109.129:32829)
I20260812 06:16:38.867170 10678 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015809889s
I20260812 06:16:38.867723 10942 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47424
I20260812 06:16:38.875072 10942 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47432:
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:38.884424 11055 tablet_service.cc:1511] Processing CreateTablet for tablet ff0e52d452df4bb58ec320fec87c64ee (DEFAULT_TABLE table=heavy-update-compaction-test [id=d260b1590f314422ab17f476ed2bd180]), partition=
I20260812 06:16:38.884778 11055 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ff0e52d452df4bb58ec320fec87c64ee. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.887446 11109 tablet_bootstrap.cc:492] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Bootstrap starting.
I20260812 06:16:38.888351 11109 tablet_bootstrap.cc:654] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.889688 11109 tablet_bootstrap.cc:492] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: No bootstrap required, opened a new log
I20260812 06:16:38.889814 11109 ts_tablet_manager.cc:1403] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:38.890426 11109 raft_consensus.cc:359] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0196ea1d6ad141bea6dd78baad6409d9" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 32829 } }
I20260812 06:16:38.890576 11109 raft_consensus.cc:385] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.890626 11109 raft_consensus.cc:740] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0196ea1d6ad141bea6dd78baad6409d9, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.890806 11109 consensus_queue.cc:260] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [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: "0196ea1d6ad141bea6dd78baad6409d9" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 32829 } }
I20260812 06:16:38.890913 11109 raft_consensus.cc:399] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.890961 11109 raft_consensus.cc:493] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.891017 11109 raft_consensus.cc:3060] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.891947 11109 raft_consensus.cc:515] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0196ea1d6ad141bea6dd78baad6409d9" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 32829 } }
I20260812 06:16:38.892117 11109 leader_election.cc:304] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [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: 0196ea1d6ad141bea6dd78baad6409d9; no voters: 
I20260812 06:16:38.892364 11109 leader_election.cc:290] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.892529 11112 raft_consensus.cc:2804] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.892750 11097 heartbeater.cc:499] Master 127.10.109.190:45073 was elected leader, sending a full tablet report...
I20260812 06:16:38.892832 11112 raft_consensus.cc:697] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 1 LEADER]: Becoming Leader. State: Replica: 0196ea1d6ad141bea6dd78baad6409d9, State: Running, Role: LEADER
I20260812 06:16:38.892736 11109 ts_tablet_manager.cc:1434] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:38.893004 11112 consensus_queue.cc:237] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [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: "0196ea1d6ad141bea6dd78baad6409d9" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 32829 } }
I20260812 06:16:38.894619 10941 catalog_manager.cc:5719] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0196ea1d6ad141bea6dd78baad6409d9 (127.10.109.129). New cstate: current_term: 1 leader_uuid: "0196ea1d6ad141bea6dd78baad6409d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0196ea1d6ad141bea6dd78baad6409d9" member_type: VOTER last_known_addr { host: "127.10.109.129" port: 32829 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.956629 10678 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.017s	sys 0.007s
I20260812 06:16:39.103440 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=18.062753
I20260812 06:16:39.301574 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.198s	user 0.111s	sys 0.079s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":167,"dirs.run_wall_time_us":924,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":64913,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:16:39.302340 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling LogGCOp(ff0e52d452df4bb58ec320fec87c64ee): free 20743880 bytes of WAL
I20260812 06:16:39.302644 11028 log_reader.cc:385] T ff0e52d452df4bb58ec320fec87c64ee: removed 2 log segments from log reader
I20260812 06:16:39.302708 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000001 (ops 1-6)
I20260812 06:16:39.302757 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000002 (ops 7-11)
I20260812 06:16:39.307077 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: LogGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:16:39.307511 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:39.319362 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.319924 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee): 16411393 bytes on disk
I20260812 06:16:39.320395 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.320806 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:39.484630 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.164s	user 0.110s	sys 0.047s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":71,"lbm_read_time_us":11653,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25155,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":303,"threads_started":5,"update_count":2000}
I20260812 06:16:39.485148 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=11.118625
I20260812 06:16:39.525090 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.040s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16586,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:39.525815 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:39.541261 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5925,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:39.541746 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:39.675783 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.134s	user 0.106s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":9649,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23115,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2000}
I20260812 06:16:39.676653 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:39.713191 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.036s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15518,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.713716 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:39.733736 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.734369 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:39.862145 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.128s	user 0.090s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":147,"lbm_read_time_us":9212,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":39040,"update_count":2000}
I20260812 06:16:39.862964 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:39.907704 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.044s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17489,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.908236 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:39.919564 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.011s	user 0.005s	sys 0.005s 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:39.920413 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:40.052606 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.132s	user 0.100s	sys 0.032s 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":710,"lbm_read_time_us":9672,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25296,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":102528,"update_count":2000}
I20260812 06:16:40.053141 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:40.104288 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.051s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15738,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.104858 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.116007 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.116528 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:40.279708 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.163s	user 0.119s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":10979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27006,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:16:40.280323 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:40.325951 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.045s	user 0.024s	sys 0.007s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15048,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.326468 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.337913 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4209,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.338613 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:40.469008 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.130s	user 0.105s	sys 0.025s 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":525,"lbm_read_time_us":9804,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25328,"lbm_writes_lt_1ms":443,"mutex_wait_us":89,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:16:40.469694 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:40.515169 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20327,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.515681 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.527570 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.528118 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:40.560601 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":94,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1484,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1650,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:40.561352 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling LogGCOp(ff0e52d452df4bb58ec320fec87c64ee): free 111786258 bytes of WAL
I20260812 06:16:40.561622 11028 log_reader.cc:385] T ff0e52d452df4bb58ec320fec87c64ee: removed 11 log segments from log reader
I20260812 06:16:40.561687 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000003 (ops 12-16)
I20260812 06:16:40.561749 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000004 (ops 17-21)
I20260812 06:16:40.561789 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000005 (ops 22-26)
I20260812 06:16:40.561822 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000006 (ops 27-31)
I20260812 06:16:40.561858 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000007 (ops 32-36)
I20260812 06:16:40.561896 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000008 (ops 37-41)
I20260812 06:16:40.561933 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000009 (ops 42-46)
I20260812 06:16:40.561970 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000010 (ops 47-50)
I20260812 06:16:40.562012 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000011 (ops 51-55)
I20260812 06:16:40.562041 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000012 (ops 56-60)
I20260812 06:16:40.562077 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000013 (ops 61-64)
I20260812 06:16:40.587113 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: LogGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:40.587574 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee): 447 bytes on disk
I20260812 06:16:40.588053 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.588634 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=3.181125
I20260812 06:16:40.608172 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.019s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7133,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:40.608664 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.619347 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3721,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:40.619853 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:40.790877 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.171s	user 0.130s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":481,"lbm_read_time_us":12387,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32620,"lbm_writes_lt_1ms":643,"mutex_wait_us":1482,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16128,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:16:40.791685 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:40.851938 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.060s	user 0.024s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28380,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.852453 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.873395 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.021s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5989,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.873857 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:40.884487 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.010s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.884963 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.074429 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.189s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":973,"lbm_read_time_us":13087,"lbm_reads_lt_1ms":673,"lbm_write_time_us":40062,"lbm_writes_lt_1ms":643,"mutex_wait_us":744,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":3000}
I20260812 06:16:41.075078 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:41.126085 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.051s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21426,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:16:41.126690 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:41.139751 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.140497 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.310130 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.169s	user 0.127s	sys 0.037s 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":194,"lbm_read_time_us":10134,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31738,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2500}
I20260812 06:16:41.310950 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:41.354805 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.044s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19886,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.355492 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.514606 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.159s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672159,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1090,"lbm_read_time_us":11263,"lbm_reads_lt_1ms":467,"lbm_write_time_us":26017,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2000}
I20260812 06:16:41.515300 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:41.557292 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.042s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17386,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.557960 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:41.570739 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.571408 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.697190 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.126s	user 0.099s	sys 0.024s 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":962,"lbm_read_time_us":7779,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22982,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16768,"update_count":2000}
I20260812 06:16:41.697808 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:41.737177 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.039s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16559,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.737854 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:41.751657 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.752286 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.883122 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.131s	user 0.101s	sys 0.028s 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":647,"lbm_read_time_us":9792,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25427,"lbm_writes_lt_1ms":443,"mutex_wait_us":1590,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2000}
I20260812 06:16:41.883981 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=10.126437
I20260812 06:16:41.922254 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.038s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16459,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.922801 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:41.934429 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.011s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.935168 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:41.966849 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.031s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1292,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2028,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:41.967630 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling LogGCOp(ff0e52d452df4bb58ec320fec87c64ee): free 120553382 bytes of WAL
I20260812 06:16:41.967845 11028 log_reader.cc:385] T ff0e52d452df4bb58ec320fec87c64ee: removed 12 log segments from log reader
I20260812 06:16:41.967898 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000014 (ops 65-69)
I20260812 06:16:41.967936 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000015 (ops 70-74)
I20260812 06:16:41.967973 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000016 (ops 75-79)
I20260812 06:16:41.967998 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000017 (ops 80-84)
I20260812 06:16:41.968019 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000018 (ops 85-88)
I20260812 06:16:41.968046 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000019 (ops 89-93)
I20260812 06:16:41.968076 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000020 (ops 94-98)
I20260812 06:16:41.968111 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000021 (ops 99-103)
I20260812 06:16:41.968194 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000022 (ops 104-108)
I20260812 06:16:41.968235 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000023 (ops 109-112)
I20260812 06:16:41.968256 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000024 (ops 113-117)
I20260812 06:16:41.968278 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000025 (ops 118-122)
I20260812 06:16:41.997800 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: LogGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:16:41.998185 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:42.014659 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.016s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4207,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.015105 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:42.026942 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.027746 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:42.192101 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.164s	user 0.140s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":734,"lbm_read_time_us":11547,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33211,"lbm_writes_lt_1ms":643,"mutex_wait_us":97,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":118528,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:16:42.192795 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:42.248298 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.055s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.248787 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee): 462 bytes on disk
I20260812 06:16:42.249193 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee) 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:42.249681 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:42.261735 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.262312 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:42.416760 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.154s	user 0.121s	sys 0.032s 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":547,"lbm_read_time_us":12224,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29824,"lbm_writes_lt_1ms":543,"mutex_wait_us":206,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:16:42.417531 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=12.110812
I20260812 06:16:42.461489 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":13784349,"delete_count":0,"lbm_write_time_us":21595,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1680}
I20260812 06:16:42.462167 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.196750
I20260812 06:16:42.483534 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":2625754,"delete_count":0,"lbm_write_time_us":4466,"lbm_writes_lt_1ms":67,"reinsert_count":0,"update_count":320}
I20260812 06:16:42.484118 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:42.494735 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.010s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4102,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.495235 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:42.663080 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.167s	user 0.121s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774762,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":968,"lbm_read_time_us":12200,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30713,"lbm_writes_lt_1ms":543,"mutex_wait_us":259,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:42.663813 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:42.724427 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.060s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21652,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.724984 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:42.735930 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.736419 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:42.917407 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.181s	user 0.118s	sys 0.052s 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":294,"lbm_read_time_us":11278,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31715,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2500}
I20260812 06:16:42.917920 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:42.992635 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.075s	user 0.018s	sys 0.051s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28499,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.993399 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:43.011459 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.012248 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:43.202656 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.190s	user 0.111s	sys 0.073s 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":1023,"lbm_read_time_us":13319,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31110,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:16:43.203452 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:43.261250 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.058s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409946,"delete_count":0,"lbm_write_time_us":17686,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.261909 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:43.278961 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6390,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.279820 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:43.490319 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.210s	user 0.139s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":580,"lbm_read_time_us":15648,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32937,"lbm_writes_lt_1ms":543,"mutex_wait_us":112,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22528,"update_count":2500}
I20260812 06:16:43.490880 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=14.095187
I20260812 06:16:43.542068 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:43.542752 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=2.188937
I20260812 06:16:43.555902 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:43.556396 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:43.591144 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushMRSOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.035s	user 0.029s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1487,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1627,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:16:43.591861 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling LogGCOp(ff0e52d452df4bb58ec320fec87c64ee): free 133024626 bytes of WAL
I20260812 06:16:43.592087 11028 log_reader.cc:385] T ff0e52d452df4bb58ec320fec87c64ee: removed 13 log segments from log reader
I20260812 06:16:43.592147 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000026 (ops 123-127)
I20260812 06:16:43.592207 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000027 (ops 128-132)
I20260812 06:16:43.592267 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000028 (ops 133-137)
I20260812 06:16:43.592307 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000029 (ops 138-142)
I20260812 06:16:43.592343 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000030 (ops 143-147)
I20260812 06:16:43.592381 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000031 (ops 148-152)
I20260812 06:16:43.592418 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000032 (ops 153-157)
I20260812 06:16:43.592454 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000033 (ops 158-162)
I20260812 06:16:43.592490 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000034 (ops 163-166)
I20260812 06:16:43.592527 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000035 (ops 167-171)
I20260812 06:16:43.592564 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000036 (ops 172-176)
I20260812 06:16:43.592600 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000037 (ops 177-181)
I20260812 06:16:43.592636 11028 log.cc:1079] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: Deleting log segment in path: /tmp/dist-test-taskjukPtn/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515392963189-10678-0/minicluster-data/ts-0-root/wals/ff0e52d452df4bb58ec320fec87c64ee/wal-000000038 (ops 182-186)
I20260812 06:16:43.622014 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: LogGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:16:43.622843 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=5.165500
I20260812 06:16:43.639302 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":6641,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:43.639797 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee): 493 bytes on disk
I20260812 06:16:43.640237 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: UndoDeltaBlockGCOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.640789 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:43.650311 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":2932,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:16:43.650863 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=1.000000
I20260812 06:16:43.883765 10678 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.927s	user 1.801s	sys 0.174s
I20260812 06:16:43.896641 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: MajorDeltaCompactionOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.246s	user 0.163s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979697,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2011,"lbm_read_time_us":13905,"lbm_reads_lt_1ms":766,"lbm_write_time_us":42796,"lbm_writes_lt_1ms":743,"mutex_wait_us":1484,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13952,"thread_start_us":89,"threads_started":1,"update_count":3500}
I20260812 06:16:43.897550 11098 maintenance_manager.cc:419] P 0196ea1d6ad141bea6dd78baad6409d9: Scheduling FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee): perf score=18.063937
I20260812 06:16:43.940055 10678 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.056s	user 0.003s	sys 0.000s
I20260812 06:16:43.940745 10678 tablet_server.cc:179] TabletServer@127.10.109.129:0 shutting down...
I20260812 06:16:43.956238 11028 maintenance_manager.cc:643] P 0196ea1d6ad141bea6dd78baad6409d9: FlushDeltaMemStoresOp(ff0e52d452df4bb58ec320fec87c64ee) complete. Timing: real 0.058s	user 0.033s	sys 0.024s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":25554,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:43.956876 10678 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:43.957181 10678 tablet_replica.cc:333] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9: stopping tablet replica
I20260812 06:16:43.957361 10678 raft_consensus.cc:2243] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.957568 10678 raft_consensus.cc:2272] T ff0e52d452df4bb58ec320fec87c64ee P 0196ea1d6ad141bea6dd78baad6409d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.961174 10678 tablet_server.cc:196] TabletServer@127.10.109.129:0 shutdown complete.
I20260812 06:16:43.964056 10678 master.cc:562] Master@127.10.109.190:45073 shutting down...
I20260812 06:16:43.967432 10678 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.967645 10678 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.967734 10678 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6a12060d754a45c7a352337c3ab596eb: stopping tablet replica
I20260812 06:16:43.980489 10678 master.cc:584] Master@127.10.109.190:45073 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5358 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11097 ms total)

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