[==========] 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:18:08.689306 21421 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.235.126:40341
I20260812 06:18:08.690281 21421 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:18:08.690888 21421 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.697144 21429 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:18:08.697170 21421 server_base.cc:1061] running on GCE node
W20260812 06:18:08.697257 21436 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:18:08.697412 21433 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:18:08.697949 21421 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.698038 21421 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:18:08.698068 21421 hybrid_clock.cc:648] HybridClock initialized: now 1786515488698066 us; error 0 us; skew 500 ppm
I20260812 06:18:08.699723 21421 webserver.cc:533] Webserver started at http://127.20.235.126:33603/ using document root <none> and password file <none>
I20260812 06:18:08.700196 21421 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.700248 21421 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.700441 21421 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.702152 21421 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/master-0-root/instance:
uuid: "8c25936b7b014085935a5549d6a79f5d"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-j2vl"
I20260812 06:18:08.705284 21421 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:08.707180 21449 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:18:08.708093 21421 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:08.708209 21421 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/master-0-root
uuid: "8c25936b7b014085935a5549d6a79f5d"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-j2vl"
I20260812 06:18:08.708303 21421 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-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:18:08.735639 21421 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.736316 21421 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:18:08.736510 21421 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.744220 21421 rpc_server.cc:307] RPC server started. Bound to: 127.20.235.126:40341
I20260812 06:18:08.744227 21549 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.235.126:40341 every 8 connection(s)
I20260812 06:18:08.746461 21550 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:18:08.751682 21550 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: Bootstrap starting.
I20260812 06:18:08.754037 21550 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.754931 21550 log.cc:826] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:08.756493 21550 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: No bootstrap required, opened a new log
I20260812 06:18:08.759801 21550 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER }
I20260812 06:18:08.759956 21550 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.760079 21550 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c25936b7b014085935a5549d6a79f5d, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.760634 21550 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [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: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER }
I20260812 06:18:08.760807 21550 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.760874 21550 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.761035 21550 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.761869 21550 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER }
I20260812 06:18:08.762291 21550 leader_election.cc:304] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [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: 8c25936b7b014085935a5549d6a79f5d; no voters: 
I20260812 06:18:08.762593 21550 leader_election.cc:290] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.762727 21553 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.762989 21553 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 1 LEADER]: Becoming Leader. State: Replica: 8c25936b7b014085935a5549d6a79f5d, State: Running, Role: LEADER
I20260812 06:18:08.763386 21553 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [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: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER }
I20260812 06:18:08.763582 21550 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:08.765388 21555 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8c25936b7b014085935a5549d6a79f5d. Latest consensus state: current_term: 1 leader_uuid: "8c25936b7b014085935a5549d6a79f5d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER } }
I20260812 06:18:08.765332 21554 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8c25936b7b014085935a5549d6a79f5d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c25936b7b014085935a5549d6a79f5d" member_type: VOTER } }
I20260812 06:18:08.765501 21555 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.765558 21554 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:08.765865 21421 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:08.765918 21580 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:08.768002 21580 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:08.772153 21580 catalog_manager.cc:1383] Generated new cluster ID: 6c0dab45f7bc4aad9146c00462f3dd57
I20260812 06:18:08.772214 21580 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:08.783421 21580 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:08.784431 21580 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:08.794528 21580 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: Generated new TSK 0
I20260812 06:18:08.795214 21580 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:08.798250 21421 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:08.800700 21587 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:18:08.800798 21592 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:18:08.800904 21586 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:18:08.801011 21421 server_base.cc:1061] running on GCE node
I20260812 06:18:08.801235 21421 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:08.801304 21421 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:18:08.801365 21421 hybrid_clock.cc:648] HybridClock initialized: now 1786515488801365 us; error 0 us; skew 500 ppm
I20260812 06:18:08.802292 21421 webserver.cc:533] Webserver started at http://127.20.235.65:37469/ using document root <none> and password file <none>
I20260812 06:18:08.802484 21421 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:08.802531 21421 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:08.802627 21421 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:08.802980 21421 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/instance:
uuid: "d998aa4765e040319a341f671460b1b1"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-j2vl"
I20260812 06:18:08.804513 21421 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:08.805593 21598 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:18:08.805845 21421 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:08.805917 21421 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root
uuid: "d998aa4765e040319a341f671460b1b1"
format_stamp: "Formatted at 2026-08-12 06:18:08 on dist-test-slave-j2vl"
I20260812 06:18:08.806005 21421 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-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:18:08.834873 21421 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:08.835372 21421 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:08.835892 21421 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:08.836831 21421 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:08.836885 21421 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.836951 21421 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:08.836992 21421 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:08.843876 21421 rpc_server.cc:307] RPC server started. Bound to: 127.20.235.65:45505
I20260812 06:18:08.843923 21704 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.235.65:45505 every 8 connection(s)
I20260812 06:18:08.857399 21705 heartbeater.cc:344] Connected to a master server at 127.20.235.126:40341
I20260812 06:18:08.857658 21705 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:08.858090 21705 heartbeater.cc:507] Master 127.20.235.126:40341 requested a full tablet report, sending...
I20260812 06:18:08.859405 21478 ts_manager.cc:194] Registered new tserver with Master: d998aa4765e040319a341f671460b1b1 (127.20.235.65:45505)
I20260812 06:18:08.860181 21421 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015651982s
I20260812 06:18:08.860589 21478 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44516
I20260812 06:18:08.869766 21478 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44528:
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:18:08.883522 21652 tablet_service.cc:1511] Processing CreateTablet for tablet ddb3110862fd4663bbef76b8b38ec6e3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=816f4d078b1d43a7bdf7142393c449ea]), partition=
I20260812 06:18:08.883993 21652 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ddb3110862fd4663bbef76b8b38ec6e3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:08.886307 21731 tablet_bootstrap.cc:492] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Bootstrap starting.
I20260812 06:18:08.887122 21731 tablet_bootstrap.cc:654] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:08.888335 21731 tablet_bootstrap.cc:492] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: No bootstrap required, opened a new log
I20260812 06:18:08.888427 21731 ts_tablet_manager.cc:1403] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:08.888885 21731 raft_consensus.cc:359] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d998aa4765e040319a341f671460b1b1" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 45505 } }
I20260812 06:18:08.888985 21731 raft_consensus.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:08.889008 21731 raft_consensus.cc:740] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d998aa4765e040319a341f671460b1b1, State: Initialized, Role: FOLLOWER
I20260812 06:18:08.889163 21731 consensus_queue.cc:260] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [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: "d998aa4765e040319a341f671460b1b1" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 45505 } }
I20260812 06:18:08.889254 21731 raft_consensus.cc:399] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:08.889282 21731 raft_consensus.cc:493] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:08.889391 21731 raft_consensus.cc:3060] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:08.890167 21731 raft_consensus.cc:515] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d998aa4765e040319a341f671460b1b1" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 45505 } }
I20260812 06:18:08.890282 21731 leader_election.cc:304] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [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: d998aa4765e040319a341f671460b1b1; no voters: 
I20260812 06:18:08.890553 21731 leader_election.cc:290] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:08.890642 21739 raft_consensus.cc:2804] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:08.890836 21739 raft_consensus.cc:697] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 1 LEADER]: Becoming Leader. State: Replica: d998aa4765e040319a341f671460b1b1, State: Running, Role: LEADER
I20260812 06:18:08.891010 21731 ts_tablet_manager.cc:1434] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:18:08.891003 21739 consensus_queue.cc:237] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [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: "d998aa4765e040319a341f671460b1b1" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 45505 } }
I20260812 06:18:08.891721 21705 heartbeater.cc:499] Master 127.20.235.126:40341 was elected leader, sending a full tablet report...
I20260812 06:18:08.894111 21478 catalog_manager.cc:5719] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 reported cstate change: term changed from 0 to 1, leader changed from <none> to d998aa4765e040319a341f671460b1b1 (127.20.235.65). New cstate: current_term: 1 leader_uuid: "d998aa4765e040319a341f671460b1b1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d998aa4765e040319a341f671460b1b1" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 45505 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:08.956233 21421 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.018s	sys 0.009s
I20260812 06:18:09.095213 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=19.054940
I20260812 06:18:09.291740 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.196s	user 0.139s	sys 0.052s Metrics: {"bytes_written":16409901,"cfile_init":1,"compiler_manager_pool.queue_time_us":226,"delete_count":0,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1693,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49358,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":143,"threads_started":1,"update_count":2000}
I20260812 06:18:09.293208 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3): free 20743880 bytes of WAL
I20260812 06:18:09.293684 21608 log_reader.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3: removed 2 log segments from log reader
I20260812 06:18:09.293828 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000001 (ops 1-6)
I20260812 06:18:09.293954 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000002 (ops 7-11)
I20260812 06:18:09.299928 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:09.300349 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3): 16411392 bytes on disk
I20260812 06:18:09.301072 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.301613 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=3.181125
I20260812 06:18:09.333576 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.032s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4744,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:09.334017 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:09.343171 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3468,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.343611 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:09.543890 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.200s	user 0.118s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877209,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":579,"lbm_read_time_us":12959,"lbm_reads_lt_1ms":669,"lbm_write_time_us":34193,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":311,"threads_started":5,"update_count":3000}
I20260812 06:18:09.544378 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:09.602826 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.058s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22289,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.603251 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:09.613423 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.613790 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:09.780663 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.167s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":345,"lbm_read_time_us":10806,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27987,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:09.781324 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:09.836549 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.055s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18868,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.837136 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:09.853777 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.016s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.854355 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.023617 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.169s	user 0.124s	sys 0.044s 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":796,"lbm_read_time_us":11304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29933,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:10.024358 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:10.059659 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.035s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15109,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.060259 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:10.076013 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6237,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.076524 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.229386 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.153s	user 0.089s	sys 0.056s 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":986,"lbm_read_time_us":8713,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27158,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":240,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2000}
I20260812 06:18:10.230067 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:10.271481 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.041s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14492,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.272125 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:10.282977 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3940,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.283727 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.411152 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.127s	user 0.093s	sys 0.034s 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":850,"lbm_read_time_us":9427,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23307,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":139136,"update_count":2000}
I20260812 06:18:10.411688 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:10.454602 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.043s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16876,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:10.455117 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:10.470134 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.470719 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.500020 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1490,"drs_written":1,"lbm_read_time_us":113,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:10.500792 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3): free 115943169 bytes of WAL
I20260812 06:18:10.501013 21608 log_reader.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3: removed 11 log segments from log reader
I20260812 06:18:10.501075 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000003 (ops 12-16)
I20260812 06:18:10.501128 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000004 (ops 17-21)
I20260812 06:18:10.501185 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000005 (ops 22-26)
I20260812 06:18:10.501225 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000006 (ops 27-31)
I20260812 06:18:10.501262 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000007 (ops 32-36)
I20260812 06:18:10.501303 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000008 (ops 37-41)
I20260812 06:18:10.501364 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000009 (ops 42-46)
I20260812 06:18:10.501405 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000010 (ops 47-51)
I20260812 06:18:10.501443 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000011 (ops 52-56)
I20260812 06:18:10.501479 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000012 (ops 57-61)
I20260812 06:18:10.501515 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000013 (ops 62-66)
I20260812 06:18:10.526628 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:10.526997 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3): 448 bytes on disk
I20260812 06:18:10.527398 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.527931 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=5.165500
I20260812 06:18:10.546336 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":6974353,"delete_count":0,"lbm_write_time_us":7588,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:18:10.546823 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.553416 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.006s	user 0.006s	sys 0.000s Metrics: {"bytes_written":1230902,"delete_count":0,"lbm_write_time_us":1776,"lbm_writes_lt_1ms":33,"reinsert_count":0,"update_count":150}
I20260812 06:18:10.553866 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.719527 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.165s	user 0.130s	sys 0.035s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":631,"lbm_read_time_us":11965,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33525,"lbm_writes_lt_1ms":643,"mutex_wait_us":307,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:10.720007 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:10.778815 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.059s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22935,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:10.779423 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:10.791393 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4563,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.791911 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:10.944749 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.153s	user 0.118s	sys 0.033s 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":660,"lbm_read_time_us":10609,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28267,"lbm_writes_lt_1ms":543,"mutex_wait_us":240,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2500}
I20260812 06:18:10.945608 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:11.006933 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.061s	user 0.045s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26175,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:11.007601 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:11.154601 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.147s	user 0.107s	sys 0.038s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":221,"lbm_read_time_us":12203,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24548,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2000}
I20260812 06:18:11.155274 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=11.118625
I20260812 06:18:11.193032 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.038s	user 0.028s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15918,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:11.193643 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:11.206851 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5235,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:11.207295 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:11.336534 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.129s	user 0.099s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":8900,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24622,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:11.337074 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:11.376286 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.039s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16776,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.376889 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:11.387888 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.388362 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:11.519111 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.131s	user 0.094s	sys 0.036s 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":637,"lbm_read_time_us":9944,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24616,"lbm_writes_lt_1ms":443,"mutex_wait_us":213,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":2000}
I20260812 06:18:11.519593 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:11.557089 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.037s	user 0.020s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13135,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.557662 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:11.568210 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s 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:18:11.569026 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:11.692752 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.123s	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":250,"lbm_read_time_us":8083,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24456,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:11.693315 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:11.745466 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.052s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14586,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.745970 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:11.756325 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.756752 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:11.905885 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.149s	user 0.096s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":787,"lbm_read_time_us":11962,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23525,"lbm_writes_lt_1ms":443,"mutex_wait_us":259,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:18:11.906476 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=10.126437
I20260812 06:18:11.942677 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15243,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:11.943164 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:11.962580 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:11.963136 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:12.012684 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.049s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1567,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1738,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:12.013513 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3): free 121006388 bytes of WAL
I20260812 06:18:12.013731 21608 log_reader.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3: removed 12 log segments from log reader
I20260812 06:18:12.013777 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000014 (ops 67-71)
I20260812 06:18:12.013830 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000015 (ops 72-76)
I20260812 06:18:12.013876 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000016 (ops 77-81)
I20260812 06:18:12.013918 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000017 (ops 82-86)
I20260812 06:18:12.013962 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000018 (ops 87-91)
I20260812 06:18:12.014021 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000019 (ops 92-96)
I20260812 06:18:12.014063 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000020 (ops 97-100)
I20260812 06:18:12.014106 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000021 (ops 101-105)
I20260812 06:18:12.014148 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000022 (ops 106-110)
I20260812 06:18:12.014187 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000023 (ops 111-115)
I20260812 06:18:12.014226 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000024 (ops 116-120)
I20260812 06:18:12.014266 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000025 (ops 121-125)
I20260812 06:18:12.039548 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:12.044284 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=6.157687
I20260812 06:18:12.065196 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8680,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:12.065722 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3): free 8767182 bytes of WAL
I20260812 06:18:12.065917 21608 log_reader.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3: removed 1 log segments from log reader
I20260812 06:18:12.065968 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000026 (ops 126-130)
I20260812 06:18:12.068104 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:12.068430 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3): 492 bytes on disk
I20260812 06:18:12.068899 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:12.069485 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:12.086352 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.017s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.087080 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:12.308333 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.221s	user 0.155s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":522,"lbm_read_time_us":16196,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38117,"lbm_writes_lt_1ms":743,"mutex_wait_us":304,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11904,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:18:12.309926 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=17.071750
I20260812 06:18:12.369295 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.059s	user 0.033s	sys 0.016s Metrics: {"bytes_written":18707249,"delete_count":0,"lbm_write_time_us":23875,"lbm_writes_lt_1ms":459,"reinsert_count":0,"update_count":2280}
I20260812 06:18:12.369831 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.196750
I20260812 06:18:12.379587 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.001s	sys 0.004s Metrics: {"bytes_written":2215508,"delete_count":0,"lbm_write_time_us":2245,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:18:12.380049 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:12.389175 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3444,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:12.389725 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:12.586859 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.197s	user 0.109s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877162,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":178,"lbm_read_time_us":14087,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32064,"lbm_writes_lt_1ms":643,"mutex_wait_us":60,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":3000}
I20260812 06:18:12.587471 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=16.079562
I20260812 06:18:12.637502 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.050s	user 0.037s	sys 0.012s Metrics: {"bytes_written":17763703,"delete_count":0,"lbm_write_time_us":21628,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:18:12.638159 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.196750
I20260812 06:18:12.660096 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.022s	user 0.007s	sys 0.000s Metrics: {"bytes_written":2748830,"delete_count":0,"lbm_write_time_us":3199,"lbm_writes_lt_1ms":70,"reinsert_count":0,"update_count":335}
I20260812 06:18:12.660575 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:12.671442 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.672084 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:12.869681 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.197s	user 0.135s	sys 0.062s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877192,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":130,"lbm_read_time_us":14334,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34819,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:18:12.870549 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:12.926673 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.056s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:12.927207 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:12.937578 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3955,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:12.938148 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:13.117724 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.179s	user 0.114s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":471,"lbm_read_time_us":12522,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30877,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:13.118501 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:13.174650 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.056s	user 0.027s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21299,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.175220 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:13.185544 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.185971 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:13.358999 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.173s	user 0.097s	sys 0.064s 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":159,"lbm_read_time_us":11784,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26413,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:13.359828 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:13.417164 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.057s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18909,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:13.417785 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:13.434191 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.016s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6167,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.434803 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:13.474359 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushMRSOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.039s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":173,"dirs.run_wall_time_us":1384,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1332,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:13.475239 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3): free 120100592 bytes of WAL
I20260812 06:18:13.475487 21608 log_reader.cc:385] T ddb3110862fd4663bbef76b8b38ec6e3: removed 12 log segments from log reader
I20260812 06:18:13.475559 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000027 (ops 131-134)
I20260812 06:18:13.475610 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000028 (ops 135-139)
I20260812 06:18:13.475667 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000029 (ops 140-144)
I20260812 06:18:13.475711 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000030 (ops 145-149)
I20260812 06:18:13.475749 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000031 (ops 150-154)
I20260812 06:18:13.475787 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000032 (ops 155-158)
I20260812 06:18:13.475827 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000033 (ops 159-163)
I20260812 06:18:13.475867 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000034 (ops 164-168)
I20260812 06:18:13.475905 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000035 (ops 169-172)
I20260812 06:18:13.475936 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000036 (ops 173-177)
I20260812 06:18:13.475991 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000037 (ops 178-182)
I20260812 06:18:13.476025 21608 log.cc:1079] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ddb3110862fd4663bbef76b8b38ec6e3/wal-000000038 (ops 183-187)
I20260812 06:18:13.499522 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: LogGCOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:13.500015 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:13.521807 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.022s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.522239 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3): 462 bytes on disk
I20260812 06:18:13.522632 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: UndoDeltaBlockGCOp(ddb3110862fd4663bbef76b8b38ec6e3) 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:18:13.523136 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:13.533263 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3932,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.533792 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:13.761312 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.227s	user 0.167s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":83,"lbm_read_time_us":15368,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41597,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:13.762039 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=14.095187
I20260812 06:18:13.781486 21421 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.825s	user 1.814s	sys 0.166s
I20260812 06:18:13.800619 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.038s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18260,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:13.801152 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=2.188937
I20260812 06:18:13.817304 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: FlushDeltaMemStoresOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:13.817885 21706 maintenance_manager.cc:419] P d998aa4765e040319a341f671460b1b1: Scheduling MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3): perf score=1.000000
I20260812 06:18:13.826365 21421 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.044s	user 0.003s	sys 0.000s
I20260812 06:18:13.826988 21421 tablet_server.cc:179] TabletServer@127.20.235.65:0 shutting down...
I20260812 06:18:13.956607 21608 maintenance_manager.cc:643] P d998aa4765e040319a341f671460b1b1: MajorDeltaCompactionOp(ddb3110862fd4663bbef76b8b38ec6e3) complete. Timing: real 0.139s	user 0.096s	sys 0.042s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":502,"cfile_cache_miss_bytes":20512297,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":531,"lbm_read_time_us":7886,"lbm_reads_lt_1ms":518,"lbm_write_time_us":24040,"lbm_writes_lt_1ms":543,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:18:13.958026 21421 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:13.958463 21421 tablet_replica.cc:333] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1: stopping tablet replica
I20260812 06:18:13.958704 21421 raft_consensus.cc:2243] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:13.958950 21421 raft_consensus.cc:2272] T ddb3110862fd4663bbef76b8b38ec6e3 P d998aa4765e040319a341f671460b1b1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:13.963917 21421 tablet_server.cc:196] TabletServer@127.20.235.65:0 shutdown complete.
I20260812 06:18:14.003165 21421 master.cc:562] Master@127.20.235.126:40341 shutting down...
I20260812 06:18:14.007354 21421 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:14.007532 21421 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:14.007588 21421 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8c25936b7b014085935a5549d6a79f5d: stopping tablet replica
I20260812 06:18:14.019929 21421 master.cc:584] Master@127.20.235.126:40341 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5418 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:14.106989 21421 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.20.235.126:42781
I20260812 06:18:14.107323 21421 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.109658 21766 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:18:14.109797 21771 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:18:14.109881 21768 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:18:14.110023 21421 server_base.cc:1061] running on GCE node
I20260812 06:18:14.110214 21421 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.110253 21421 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:18:14.110270 21421 hybrid_clock.cc:648] HybridClock initialized: now 1786515494110269 us; error 0 us; skew 500 ppm
I20260812 06:18:14.111092 21421 webserver.cc:533] Webserver started at http://127.20.235.126:45925/ using document root <none> and password file <none>
I20260812 06:18:14.111267 21421 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.111310 21421 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.111464 21421 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.111848 21421 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/master-0-root/instance:
uuid: "e14330d019e14e7a9e170c6bc8e1da10"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-j2vl"
I20260812 06:18:14.113286 21421 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:14.114198 21778 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:18:14.114471 21421 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:14.114562 21421 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/master-0-root
uuid: "e14330d019e14e7a9e170c6bc8e1da10"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-j2vl"
I20260812 06:18:14.114645 21421 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-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:18:14.124171 21421 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.124534 21421 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.128794 21421 rpc_server.cc:307] RPC server started. Bound to: 127.20.235.126:42781
I20260812 06:18:14.130777 21866 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.235.126:42781 every 8 connection(s)
I20260812 06:18:14.131719 21870 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:18:14.147069 21870 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10: Bootstrap starting.
I20260812 06:18:14.147883 21870 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.148891 21870 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10: No bootstrap required, opened a new log
I20260812 06:18:14.149261 21870 raft_consensus.cc:359] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER }
I20260812 06:18:14.149360 21870 raft_consensus.cc:385] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.149384 21870 raft_consensus.cc:740] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e14330d019e14e7a9e170c6bc8e1da10, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.149536 21870 consensus_queue.cc:260] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [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: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER }
I20260812 06:18:14.149627 21870 raft_consensus.cc:399] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.149652 21870 raft_consensus.cc:493] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.149684 21870 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.150346 21870 raft_consensus.cc:515] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER }
I20260812 06:18:14.150462 21870 leader_election.cc:304] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [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: e14330d019e14e7a9e170c6bc8e1da10; no voters: 
I20260812 06:18:14.150602 21870 leader_election.cc:290] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.150772 21877 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.150971 21877 raft_consensus.cc:697] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 1 LEADER]: Becoming Leader. State: Replica: e14330d019e14e7a9e170c6bc8e1da10, State: Running, Role: LEADER
I20260812 06:18:14.151106 21870 sys_catalog.cc:565] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:14.151135 21877 consensus_queue.cc:237] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [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: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER }
I20260812 06:18:14.151572 21881 sys_catalog.cc:455] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e14330d019e14e7a9e170c6bc8e1da10. Latest consensus state: current_term: 1 leader_uuid: "e14330d019e14e7a9e170c6bc8e1da10" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER } }
I20260812 06:18:14.151671 21881 sys_catalog.cc:458] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.151556 21879 sys_catalog.cc:455] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e14330d019e14e7a9e170c6bc8e1da10" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e14330d019e14e7a9e170c6bc8e1da10" member_type: VOTER } }
I20260812 06:18:14.151723 21879 sys_catalog.cc:458] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:14.151981 21884 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:14.152799 21884 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:14.153070 21421 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:14.154592 21884 catalog_manager.cc:1383] Generated new cluster ID: 7d32d5c2591d4dea9d00f18f7f97ac26
I20260812 06:18:14.154649 21884 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:14.167166 21884 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:14.167750 21884 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:14.177238 21884 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10: Generated new TSK 0
I20260812 06:18:14.177457 21884 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:14.185497 21421 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:14.187741 21913 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:18:14.187717 21915 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:18:14.187696 21421 server_base.cc:1061] running on GCE node
W20260812 06:18:14.187808 21911 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:18:14.188181 21421 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:14.188237 21421 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:18:14.188303 21421 hybrid_clock.cc:648] HybridClock initialized: now 1786515494188302 us; error 0 us; skew 500 ppm
I20260812 06:18:14.189138 21421 webserver.cc:533] Webserver started at http://127.20.235.65:43289/ using document root <none> and password file <none>
I20260812 06:18:14.189321 21421 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:14.189419 21421 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:14.189502 21421 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:14.189917 21421 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/instance:
uuid: "b21ee947a9c84885ab301170180ab9c8"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-j2vl"
I20260812 06:18:14.191457 21421 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:14.192407 21924 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:18:14.192723 21421 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:14.192826 21421 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root
uuid: "b21ee947a9c84885ab301170180ab9c8"
format_stamp: "Formatted at 2026-08-12 06:18:14 on dist-test-slave-j2vl"
I20260812 06:18:14.192924 21421 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-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:18:14.214668 21421 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:14.215085 21421 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:14.215415 21421 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:14.215965 21421 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:14.216029 21421 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.216091 21421 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:14.216141 21421 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:14.220407 21421 rpc_server.cc:307] RPC server started. Bound to: 127.20.235.65:34093
I20260812 06:18:14.220453 22042 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.20.235.65:34093 every 8 connection(s)
I20260812 06:18:14.228935 22043 heartbeater.cc:344] Connected to a master server at 127.20.235.126:42781
I20260812 06:18:14.229065 22043 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:14.229285 22043 heartbeater.cc:507] Master 127.20.235.126:42781 requested a full tablet report, sending...
I20260812 06:18:14.230020 21809 ts_manager.cc:194] Registered new tserver with Master: b21ee947a9c84885ab301170180ab9c8 (127.20.235.65:34093)
I20260812 06:18:14.230748 21809 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:43042
I20260812 06:18:14.230760 21421 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009907042s
I20260812 06:18:14.237197 21809 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:43054:
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:18:14.245659 21973 tablet_service.cc:1511] Processing CreateTablet for tablet ead5786a44ca4491aab0abdbd6b2c1d3 (DEFAULT_TABLE table=heavy-update-compaction-test [id=cdaa7579a2494df4a1ff78734b81ec45]), partition=
I20260812 06:18:14.245893 21973 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ead5786a44ca4491aab0abdbd6b2c1d3. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:14.247728 22068 tablet_bootstrap.cc:492] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Bootstrap starting.
I20260812 06:18:14.248703 22068 tablet_bootstrap.cc:654] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:14.249801 22068 tablet_bootstrap.cc:492] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: No bootstrap required, opened a new log
I20260812 06:18:14.249925 22068 ts_tablet_manager.cc:1403] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:14.250340 22068 raft_consensus.cc:359] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b21ee947a9c84885ab301170180ab9c8" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 34093 } }
I20260812 06:18:14.250429 22068 raft_consensus.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:14.250488 22068 raft_consensus.cc:740] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b21ee947a9c84885ab301170180ab9c8, State: Initialized, Role: FOLLOWER
I20260812 06:18:14.250653 22068 consensus_queue.cc:260] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [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: "b21ee947a9c84885ab301170180ab9c8" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 34093 } }
I20260812 06:18:14.250727 22068 raft_consensus.cc:399] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:14.250787 22068 raft_consensus.cc:493] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:14.250854 22068 raft_consensus.cc:3060] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:14.251722 22068 raft_consensus.cc:515] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b21ee947a9c84885ab301170180ab9c8" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 34093 } }
I20260812 06:18:14.251837 22068 leader_election.cc:304] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [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: b21ee947a9c84885ab301170180ab9c8; no voters: 
I20260812 06:18:14.251987 22068 leader_election.cc:290] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:14.252117 22072 raft_consensus.cc:2804] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:14.252347 22043 heartbeater.cc:499] Master 127.20.235.126:42781 was elected leader, sending a full tablet report...
I20260812 06:18:14.252385 22072 raft_consensus.cc:697] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 1 LEADER]: Becoming Leader. State: Replica: b21ee947a9c84885ab301170180ab9c8, State: Running, Role: LEADER
I20260812 06:18:14.252563 22072 consensus_queue.cc:237] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [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: "b21ee947a9c84885ab301170180ab9c8" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 34093 } }
I20260812 06:18:14.252630 22068 ts_tablet_manager.cc:1434] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:14.253984 21809 catalog_manager.cc:5719] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 reported cstate change: term changed from 0 to 1, leader changed from <none> to b21ee947a9c84885ab301170180ab9c8 (127.20.235.65). New cstate: current_term: 1 leader_uuid: "b21ee947a9c84885ab301170180ab9c8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b21ee947a9c84885ab301170180ab9c8" member_type: VOTER last_known_addr { host: "127.20.235.65" port: 34093 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:14.311594 21421 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.014s	sys 0.008s
I20260812 06:18:14.471295 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=19.054940
I20260812 06:18:14.624023 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.152s	user 0.098s	sys 0.052s Metrics: {"bytes_written":13251054,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":916,"drs_written":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40235,"lbm_writes_lt_1ms":780,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":22656,"update_count":1615}
I20260812 06:18:14.625041 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 20743880 bytes of WAL
I20260812 06:18:14.625298 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 2 log segments from log reader
I20260812 06:18:14.625411 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000001 (ops 1-6)
I20260812 06:18:14.625475 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000002 (ops 7-11)
I20260812 06:18:14.629901 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:14.630191 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:14.643469 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.013s	user 0.006s	sys 0.002s Metrics: {"bytes_written":3569334,"delete_count":0,"lbm_write_time_us":3407,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:18:14.643841 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): 16411391 bytes on disk
I20260812 06:18:14.644209 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:14.644559 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:14.654369 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3600,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:14.654726 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:14.840013 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.185s	user 0.140s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774793,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":559,"lbm_read_time_us":12109,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28808,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":367,"threads_started":5,"update_count":2500}
I20260812 06:18:14.840667 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:14.892645 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.052s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22765,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:14.893136 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:14.909641 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.016s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:14.910220 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.069455 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.159s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":10427,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31501,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":71680,"update_count":2500}
I20260812 06:18:15.070149 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=11.118625
I20260812 06:18:15.110733 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.040s	user 0.018s	sys 0.021s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17507,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:15.111204 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:15.137193 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.026s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4903,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":450}
I20260812 06:18:15.137658 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:15.147681 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3801,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.148094 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.302811 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.155s	user 0.121s	sys 0.023s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":772,"lbm_read_time_us":10235,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28830,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":29056,"update_count":2500}
I20260812 06:18:15.303417 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:15.353133 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.049s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18123,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.353708 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:15.368991 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.369591 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.520354 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.151s	user 0.117s	sys 0.024s 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":309,"lbm_read_time_us":10241,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29234,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:15.521111 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:15.566953 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.046s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18959,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:15.567457 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:15.578593 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3983,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:15.579095 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.735605 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.156s	user 0.114s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":9065,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31944,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:18:15.736452 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=13.103000
I20260812 06:18:15.784521 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.048s	user 0.020s	sys 0.025s Metrics: {"bytes_written":14686890,"delete_count":0,"lbm_write_time_us":21462,"lbm_writes_lt_1ms":361,"reinsert_count":0,"update_count":1790}
I20260812 06:18:15.785123 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.791441 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":1723202,"delete_count":0,"lbm_write_time_us":2014,"lbm_writes_lt_1ms":45,"reinsert_count":0,"update_count":210}
I20260812 06:18:15.792129 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.829169 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.037s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":262,"dirs.run_wall_time_us":1353,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2304,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:15.830247 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 112239264 bytes of WAL
I20260812 06:18:15.830700 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 11 log segments from log reader
I20260812 06:18:15.830792 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000003 (ops 12-16)
I20260812 06:18:15.830852 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000004 (ops 17-21)
I20260812 06:18:15.830928 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000005 (ops 22-26)
I20260812 06:18:15.830986 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000006 (ops 27-30)
I20260812 06:18:15.831037 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000007 (ops 31-35)
I20260812 06:18:15.831091 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000008 (ops 36-40)
I20260812 06:18:15.831148 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000009 (ops 41-45)
I20260812 06:18:15.831202 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000010 (ops 46-50)
I20260812 06:18:15.831255 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000011 (ops 51-55)
I20260812 06:18:15.831331 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000012 (ops 56-60)
I20260812 06:18:15.831387 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000013 (ops 61-65)
I20260812 06:18:15.858035 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:15.858628 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=4.173312
I20260812 06:18:15.877146 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":6071825,"delete_count":0,"lbm_write_time_us":7699,"lbm_writes_lt_1ms":151,"reinsert_count":0,"update_count":740}
I20260812 06:18:15.877569 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 8767182 bytes of WAL
I20260812 06:18:15.877777 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 1 log segments from log reader
I20260812 06:18:15.877825 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000014 (ops 66-70)
I20260812 06:18:15.879519 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:15.879827 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): 473 bytes on disk
I20260812 06:18:15.880223 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:18:15.880654 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:15.888806 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.008s	user 0.000s	sys 0.007s Metrics: {"bytes_written":2133453,"delete_count":0,"lbm_write_time_us":2871,"lbm_writes_lt_1ms":55,"reinsert_count":0,"update_count":260}
I20260812 06:18:15.889248 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:16.092885 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.203s	user 0.142s	sys 0.061s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877237,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":102,"lbm_read_time_us":13910,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35247,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:18:16.093652 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=15.087375
I20260812 06:18:16.140084 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.046s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":19869,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:16.140652 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:16.152097 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:16.152601 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:16.336117 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.183s	user 0.122s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774675,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1672,"lbm_read_time_us":13161,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27730,"lbm_writes_lt_1ms":543,"mutex_wait_us":554,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:16.336917 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:16.386346 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.049s	user 0.037s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.386941 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:16.520744 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.134s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":651,"lbm_read_time_us":11505,"lbm_reads_lt_1ms":367,"lbm_write_time_us":18242,"lbm_writes_lt_1ms":343,"mutex_wait_us":353,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":1500}
I20260812 06:18:16.521435 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:16.556631 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.035s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15967,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.557142 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:16.573056 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.573588 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:16.709295 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.136s	user 0.106s	sys 0.029s 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":712,"lbm_read_time_us":9937,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26325,"lbm_writes_lt_1ms":443,"mutex_wait_us":269,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:18:16.710251 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:16.754684 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.044s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18930,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.755165 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:16.765446 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.766386 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:16.901255 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.135s	user 0.121s	sys 0.011s 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":253,"lbm_read_time_us":11018,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25489,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":22400,"update_count":2000}
I20260812 06:18:16.901813 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:16.957069 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.055s	user 0.021s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17430,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:16.957711 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:16.969025 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4465,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:16.969570 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.125548 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.156s	user 0.103s	sys 0.053s 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":466,"lbm_read_time_us":12004,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26138,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:17.126304 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:17.163551 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.037s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16844,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.164060 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:17.176132 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4173,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.177207 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.307250 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.130s	user 0.095s	sys 0.033s 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":280,"lbm_read_time_us":9889,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25556,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:17.307945 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=10.126437
I20260812 06:18:17.348133 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.040s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16400,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:17.348708 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:17.359439 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.360009 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.396971 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.037s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":1216,"drs_written":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1627,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:17.397655 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 120553390 bytes of WAL
I20260812 06:18:17.397883 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 12 log segments from log reader
I20260812 06:18:17.397926 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000015 (ops 71-74)
I20260812 06:18:17.397954 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000016 (ops 75-79)
I20260812 06:18:17.398021 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000017 (ops 80-84)
I20260812 06:18:17.398065 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000018 (ops 85-89)
I20260812 06:18:17.398109 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000019 (ops 90-94)
I20260812 06:18:17.398161 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000020 (ops 95-99)
I20260812 06:18:17.398198 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000021 (ops 100-104)
I20260812 06:18:17.398239 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000022 (ops 105-108)
I20260812 06:18:17.398284 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000023 (ops 109-113)
I20260812 06:18:17.398324 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000024 (ops 114-118)
I20260812 06:18:17.398363 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000025 (ops 119-123)
I20260812 06:18:17.398403 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000026 (ops 124-128)
I20260812 06:18:17.424819 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.027s	user 0.004s	sys 0.020s Metrics: {}
I20260812 06:18:17.425208 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): 462 bytes on disk
I20260812 06:18:17.425705 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:18:17.426198 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=5.165500
I20260812 06:18:17.442173 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.016s	user 0.002s	sys 0.013s Metrics: {"bytes_written":6728210,"delete_count":0,"lbm_write_time_us":6725,"lbm_writes_lt_1ms":167,"reinsert_count":0,"update_count":820}
I20260812 06:18:17.442675 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.456635 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.014s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1477052,"delete_count":0,"lbm_write_time_us":2767,"lbm_writes_lt_1ms":39,"mutex_wait_us":43,"reinsert_count":0,"update_count":180}
I20260812 06:18:17.457126 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.619895 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.163s	user 0.142s	sys 0.020s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":745,"lbm_read_time_us":11945,"lbm_reads_lt_1ms":666,"lbm_write_time_us":33091,"lbm_writes_lt_1ms":643,"mutex_wait_us":284,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21632,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:18:17.620731 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:17.673580 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.053s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23772,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.674062 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:17.685182 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:17.685623 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:17.848858 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.163s	user 0.107s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":673,"lbm_read_time_us":10006,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29598,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":2500}
I20260812 06:18:17.849684 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:17.899585 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.050s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22135,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:17.900125 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:18.059587 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.159s	user 0.126s	sys 0.028s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":517,"lbm_read_time_us":10426,"lbm_reads_lt_1ms":463,"lbm_write_time_us":24560,"lbm_writes_lt_1ms":443,"mutex_wait_us":203,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:18.060277 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:18.112511 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.051s	user 0.039s	sys 0.005s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21261,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.113011 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.123881 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4041,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.124609 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:18.308418 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.184s	user 0.116s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":11543,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29799,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:18:18.309108 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:18.361193 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.052s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21874,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.361874 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.373634 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.374128 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:18.537074 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.163s	user 0.131s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":10634,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31032,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2500}
I20260812 06:18:18.537592 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:18.590163 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.052s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17881,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:18.590720 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.602532 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.603029 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:18.756968 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.154s	user 0.131s	sys 0.021s 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":396,"lbm_read_time_us":10185,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32818,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:18:18.757853 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=11.118625
I20260812 06:18:18.788475 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.030s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12734,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:18.789188 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.803807 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.804374 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:18.843412 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushMRSOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.039s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1172,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1824,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:18.844273 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): 483 bytes on disk
I20260812 06:18:18.844862 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: UndoDeltaBlockGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:18.845515 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=3.181125
I20260812 06:18:18.856987 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:18.857561 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 124257508 bytes of WAL
I20260812 06:18:18.857774 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 12 log segments from log reader
I20260812 06:18:18.857816 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000027 (ops 129-132)
I20260812 06:18:18.857843 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000028 (ops 133-137)
I20260812 06:18:18.857908 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000029 (ops 138-142)
I20260812 06:18:18.857968 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000030 (ops 143-147)
I20260812 06:18:18.858007 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000031 (ops 148-152)
I20260812 06:18:18.858044 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000032 (ops 153-157)
I20260812 06:18:18.858081 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000033 (ops 158-162)
I20260812 06:18:18.858119 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000034 (ops 163-167)
I20260812 06:18:18.858156 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000035 (ops 168-172)
I20260812 06:18:18.858193 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000036 (ops 173-177)
I20260812 06:18:18.858233 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000037 (ops 178-182)
I20260812 06:18:18.858278 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000038 (ops 183-187)
I20260812 06:18:18.885774 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:18.886149 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.896621 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:18.897040 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3): free 12017952 bytes of WAL
I20260812 06:18:18.897243 21932 log_reader.cc:385] T ead5786a44ca4491aab0abdbd6b2c1d3: removed 1 log segments from log reader
I20260812 06:18:18.897292 21932 log.cc:1079] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: Deleting log segment in path: /tmp/dist-test-task1gr_Ac/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515488678897-21421-0/minicluster-data/ts-0-root/wals/ead5786a44ca4491aab0abdbd6b2c1d3/wal-000000039 (ops 188-192)
I20260812 06:18:18.899521 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: LogGCOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:18.899812 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=2.188937
I20260812 06:18:18.921082 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:18.922008 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=1.000000
I20260812 06:18:19.101643 21421 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.790s	user 1.840s	sys 0.114s
I20260812 06:18:19.139972 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: MajorDeltaCompactionOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.218s	user 0.150s	sys 0.065s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14162,"lbm_reads_lt_1ms":763,"lbm_write_time_us":39112,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3500}
I20260812 06:18:19.140569 22044 maintenance_manager.cc:419] P b21ee947a9c84885ab301170180ab9c8: Scheduling FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3): perf score=14.095187
I20260812 06:18:19.185184 21421 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.083s	user 0.001s	sys 0.000s
I20260812 06:18:19.185694 21421 tablet_server.cc:179] TabletServer@127.20.235.65:0 shutting down...
I20260812 06:18:19.238957 21932 maintenance_manager.cc:643] P b21ee947a9c84885ab301170180ab9c8: FlushDeltaMemStoresOp(ead5786a44ca4491aab0abdbd6b2c1d3) complete. Timing: real 0.098s	user 0.023s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18261,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:19.239632 21421 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:19.239904 21421 tablet_replica.cc:333] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8: stopping tablet replica
I20260812 06:18:19.240067 21421 raft_consensus.cc:2243] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.240236 21421 raft_consensus.cc:2272] T ead5786a44ca4491aab0abdbd6b2c1d3 P b21ee947a9c84885ab301170180ab9c8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.243605 21421 tablet_server.cc:196] TabletServer@127.20.235.65:0 shutdown complete.
I20260812 06:18:19.246315 21421 master.cc:562] Master@127.20.235.126:42781 shutting down...
I20260812 06:18:19.249221 21421 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:19.249403 21421 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:19.249483 21421 tablet_replica.cc:333] T 00000000000000000000000000000000 P e14330d019e14e7a9e170c6bc8e1da10: stopping tablet replica
I20260812 06:18:19.261613 21421 master.cc:584] Master@127.20.235.126:42781 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5238 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10657 ms total)

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