[==========] 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:17:40.948988 15288 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.238.62:33287
I20260812 06:17:40.950042 15288 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:17:40.950662 15288 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:40.957387 15294 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:17:40.957484 15299 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:17:40.957633 15288 server_base.cc:1061] running on GCE node
W20260812 06:17:40.957669 15293 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:17:40.958178 15288 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:40.958268 15288 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:17:40.958299 15288 hybrid_clock.cc:648] HybridClock initialized: now 1786515460958297 us; error 0 us; skew 500 ppm
I20260812 06:17:40.960047 15288 webserver.cc:533] Webserver started at http://127.14.238.62:46351/ using document root <none> and password file <none>
I20260812 06:17:40.960532 15288 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:40.960589 15288 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:40.960767 15288 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:40.962301 15288 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/master-0-root/instance:
uuid: "df610ca1bc3746398d9bb74c6d899c0a"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-c12x"
I20260812 06:17:40.965699 15288 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:40.967746 15306 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:17:40.968762 15288 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:40.969005 15288 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/master-0-root
uuid: "df610ca1bc3746398d9bb74c6d899c0a"
format_stamp: "Formatted at 2026-08-12 06:17:40 on dist-test-slave-c12x"
I20260812 06:17:40.969123 15288 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-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:17:40.990288 15288 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:40.990959 15288 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:17:40.991149 15288 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:40.999120 15288 rpc_server.cc:307] RPC server started. Bound to: 127.14.238.62:33287
I20260812 06:17:40.999136 15387 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.238.62:33287 every 8 connection(s)
I20260812 06:17:41.001510 15388 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:17:41.007591 15388 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: Bootstrap starting.
I20260812 06:17:41.010223 15388 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:41.011142 15388 log.cc:826] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:41.012920 15388 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: No bootstrap required, opened a new log
I20260812 06:17:41.015820 15388 raft_consensus.cc:359] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER }
I20260812 06:17:41.016003 15388 raft_consensus.cc:385] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:41.016047 15388 raft_consensus.cc:740] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: df610ca1bc3746398d9bb74c6d899c0a, State: Initialized, Role: FOLLOWER
I20260812 06:17:41.016662 15388 consensus_queue.cc:260] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [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: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER }
I20260812 06:17:41.016803 15388 raft_consensus.cc:399] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:41.016849 15388 raft_consensus.cc:493] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:41.016935 15388 raft_consensus.cc:3060] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:41.017691 15388 raft_consensus.cc:515] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER }
I20260812 06:17:41.018071 15388 leader_election.cc:304] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [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: df610ca1bc3746398d9bb74c6d899c0a; no voters: 
I20260812 06:17:41.018404 15388 leader_election.cc:290] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:41.018555 15391 raft_consensus.cc:2804] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:41.018831 15391 raft_consensus.cc:697] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 1 LEADER]: Becoming Leader. State: Replica: df610ca1bc3746398d9bb74c6d899c0a, State: Running, Role: LEADER
I20260812 06:17:41.019214 15391 consensus_queue.cc:237] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [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: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER }
I20260812 06:17:41.019465 15388 sys_catalog.cc:565] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:41.021198 15394 sys_catalog.cc:455] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [sys.catalog]: SysCatalogTable state changed. Reason: New leader df610ca1bc3746398d9bb74c6d899c0a. Latest consensus state: current_term: 1 leader_uuid: "df610ca1bc3746398d9bb74c6d899c0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER } }
I20260812 06:17:41.021201 15393 sys_catalog.cc:455] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "df610ca1bc3746398d9bb74c6d899c0a" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "df610ca1bc3746398d9bb74c6d899c0a" member_type: VOTER } }
I20260812 06:17:41.021375 15394 sys_catalog.cc:458] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:41.021376 15393 sys_catalog.cc:458] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:41.021740 15407 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:41.021907 15288 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:41.024370 15407 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:41.029410 15407 catalog_manager.cc:1383] Generated new cluster ID: 7005d071d8324a959b48c4f8b272ed5c
I20260812 06:17:41.029493 15407 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:41.070305 15407 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:41.071254 15407 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:41.080608 15407 catalog_manager.cc:6092] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: Generated new TSK 0
I20260812 06:17:41.081262 15407 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:41.087105 15288 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:41.090418 15419 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:17:41.090565 15421 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:17:41.090631 15288 server_base.cc:1061] running on GCE node
W20260812 06:17:41.090680 15423 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:17:41.091003 15288 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:41.091079 15288 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:17:41.091109 15288 hybrid_clock.cc:648] HybridClock initialized: now 1786515461091107 us; error 0 us; skew 500 ppm
I20260812 06:17:41.092353 15288 webserver.cc:533] Webserver started at http://127.14.238.1:34749/ using document root <none> and password file <none>
I20260812 06:17:41.092547 15288 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:41.092623 15288 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:41.092705 15288 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:41.093132 15288 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/instance:
uuid: "8979fcc73696495baceeb0dac0a400af"
format_stamp: "Formatted at 2026-08-12 06:17:41 on dist-test-slave-c12x"
I20260812 06:17:41.094728 15288 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:41.095799 15428 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:17:41.096101 15288 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:41.096175 15288 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root
uuid: "8979fcc73696495baceeb0dac0a400af"
format_stamp: "Formatted at 2026-08-12 06:17:41 on dist-test-slave-c12x"
I20260812 06:17:41.096273 15288 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-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:17:41.112751 15288 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:41.113248 15288 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:41.113785 15288 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:41.114626 15288 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:41.114675 15288 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:41.114753 15288 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:41.114789 15288 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:41.121743 15288 rpc_server.cc:307] RPC server started. Bound to: 127.14.238.1:43691
I20260812 06:17:41.121778 15541 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.238.1:43691 every 8 connection(s)
I20260812 06:17:41.132476 15542 heartbeater.cc:344] Connected to a master server at 127.14.238.62:33287
I20260812 06:17:41.132807 15542 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:41.133247 15542 heartbeater.cc:507] Master 127.14.238.62:33287 requested a full tablet report, sending...
I20260812 06:17:41.134619 15332 ts_manager.cc:194] Registered new tserver with Master: 8979fcc73696495baceeb0dac0a400af (127.14.238.1:43691)
I20260812 06:17:41.134882 15288 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012513496s
I20260812 06:17:41.135881 15332 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50580
I20260812 06:17:41.145134 15332 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50590:
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:17:41.160873 15478 tablet_service.cc:1511] Processing CreateTablet for tablet fe56dee5a2ac4079a1c065970db938af (DEFAULT_TABLE table=heavy-update-compaction-test [id=bb4ab531f572455886b1c3dd04ae1f97]), partition=
I20260812 06:17:41.161332 15478 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fe56dee5a2ac4079a1c065970db938af. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:41.163957 15561 tablet_bootstrap.cc:492] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Bootstrap starting.
I20260812 06:17:41.165333 15561 tablet_bootstrap.cc:654] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:41.166725 15561 tablet_bootstrap.cc:492] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: No bootstrap required, opened a new log
I20260812 06:17:41.166851 15561 ts_tablet_manager.cc:1403] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:41.167415 15561 raft_consensus.cc:359] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8979fcc73696495baceeb0dac0a400af" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 43691 } }
I20260812 06:17:41.167601 15561 raft_consensus.cc:385] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:41.167642 15561 raft_consensus.cc:740] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8979fcc73696495baceeb0dac0a400af, State: Initialized, Role: FOLLOWER
I20260812 06:17:41.167851 15561 consensus_queue.cc:260] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [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: "8979fcc73696495baceeb0dac0a400af" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 43691 } }
I20260812 06:17:41.168004 15561 raft_consensus.cc:399] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:41.168112 15561 raft_consensus.cc:493] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:41.168184 15561 raft_consensus.cc:3060] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:41.169344 15561 raft_consensus.cc:515] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8979fcc73696495baceeb0dac0a400af" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 43691 } }
I20260812 06:17:41.169507 15561 leader_election.cc:304] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [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: 8979fcc73696495baceeb0dac0a400af; no voters: 
I20260812 06:17:41.169848 15561 leader_election.cc:290] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:41.169931 15563 raft_consensus.cc:2804] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:41.170195 15563 raft_consensus.cc:697] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 1 LEADER]: Becoming Leader. State: Replica: 8979fcc73696495baceeb0dac0a400af, State: Running, Role: LEADER
I20260812 06:17:41.170298 15561 ts_tablet_manager.cc:1434] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:17:41.170385 15563 consensus_queue.cc:237] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [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: "8979fcc73696495baceeb0dac0a400af" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 43691 } }
I20260812 06:17:41.170526 15542 heartbeater.cc:499] Master 127.14.238.62:33287 was elected leader, sending a full tablet report...
I20260812 06:17:41.173278 15332 catalog_manager.cc:5719] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af reported cstate change: term changed from 0 to 1, leader changed from <none> to 8979fcc73696495baceeb0dac0a400af (127.14.238.1). New cstate: current_term: 1 leader_uuid: "8979fcc73696495baceeb0dac0a400af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8979fcc73696495baceeb0dac0a400af" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 43691 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:41.246271 15288 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.065s	user 0.032s	sys 0.003s
I20260812 06:17:41.373181 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushMRSOp(fe56dee5a2ac4079a1c065970db938af): perf score=15.086190
I20260812 06:17:41.526746 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushMRSOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.153s	user 0.117s	sys 0.031s Metrics: {"bytes_written":11897251,"cfile_init":1,"compiler_manager_pool.queue_time_us":253,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":726,"drs_written":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38890,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":162,"threads_started":1,"update_count":1450}
I20260812 06:17:41.528192 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling LogGCOp(fe56dee5a2ac4079a1c065970db938af): free 20743880 bytes of WAL
I20260812 06:17:41.528648 15436 log_reader.cc:385] T fe56dee5a2ac4079a1c065970db938af: removed 2 log segments from log reader
I20260812 06:17:41.528736 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000001 (ops 1-6)
I20260812 06:17:41.528801 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000002 (ops 7-11)
I20260812 06:17:41.534276 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: LogGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:41.534947 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af): 12719216 bytes on disk
I20260812 06:17:41.535701 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:17:41.536321 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:41.555423 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.019s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.556393 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:41.684522 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.128s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262038,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":674,"lbm_read_time_us":8613,"lbm_reads_lt_1ms":450,"lbm_write_time_us":24941,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"thread_start_us":323,"threads_started":5,"update_count":1950}
I20260812 06:17:41.685202 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:41.724453 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.039s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17564,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.724952 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:41.736497 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.736974 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:41.860055 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.123s	user 0.110s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":8417,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24535,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19328,"update_count":2000}
I20260812 06:17:41.860582 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:41.898159 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.037s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15194,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:41.898644 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:41.909686 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4004,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:41.910274 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.036964 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.126s	user 0.101s	sys 0.025s 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":543,"lbm_read_time_us":9374,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23249,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:42.037415 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:42.078080 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.040s	user 0.014s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14994,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.078702 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:42.094198 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5786,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.094880 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.250684 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.156s	user 0.100s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1393,"lbm_read_time_us":10877,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25230,"lbm_writes_lt_1ms":443,"mutex_wait_us":442,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:17:42.251241 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:42.287751 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.036s	user 0.036s	sys 0.000s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16185,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.288262 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:42.304526 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.016s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6245,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.305066 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.427614 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.122s	user 0.098s	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":278,"lbm_read_time_us":8729,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25286,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.428280 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:42.468888 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.040s	user 0.035s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16143,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.469404 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:42.480756 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.481334 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.611754 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.130s	user 0.106s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":9459,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25963,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:17:42.612295 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:42.672991 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.061s	user 0.032s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17467,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.673609 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:42.684334 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.685014 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.841972 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.157s	user 0.110s	sys 0.045s 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":1196,"lbm_read_time_us":11263,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24069,"lbm_writes_lt_1ms":443,"mutex_wait_us":304,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:42.842728 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:42.886524 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.044s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16521,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:42.887133 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:42.899155 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:42.900007 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushMRSOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:42.941355 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushMRSOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.041s	user 0.036s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1616,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1927,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":1920}
I20260812 06:17:42.942209 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling LogGCOp(fe56dee5a2ac4079a1c065970db938af): free 120553329 bytes of WAL
I20260812 06:17:42.942462 15436 log_reader.cc:385] T fe56dee5a2ac4079a1c065970db938af: removed 12 log segments from log reader
I20260812 06:17:42.942510 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000003 (ops 12-16)
I20260812 06:17:42.942543 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000004 (ops 17-20)
I20260812 06:17:42.942601 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000005 (ops 21-25)
I20260812 06:17:42.942651 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000006 (ops 26-30)
I20260812 06:17:42.942690 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000007 (ops 31-34)
I20260812 06:17:42.942731 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000008 (ops 35-39)
I20260812 06:17:42.942781 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000009 (ops 40-44)
I20260812 06:17:42.942819 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000010 (ops 45-49)
I20260812 06:17:42.942867 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000011 (ops 50-54)
I20260812 06:17:42.942934 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000012 (ops 55-59)
I20260812 06:17:42.942975 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000013 (ops 60-64)
I20260812 06:17:42.943017 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000014 (ops 65-69)
I20260812 06:17:42.971838 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: LogGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.029s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:42.972420 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af): 482 bytes on disk
I20260812 06:17:42.973006 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:42.973445 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=6.157687
I20260812 06:17:43.001606 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.028s	user 0.010s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8767,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:43.002206 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling LogGCOp(fe56dee5a2ac4079a1c065970db938af): free 12017983 bytes of WAL
I20260812 06:17:43.002435 15436 log_reader.cc:385] T fe56dee5a2ac4079a1c065970db938af: removed 1 log segments from log reader
I20260812 06:17:43.002483 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000015 (ops 70-74)
I20260812 06:17:43.005013 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: LogGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:43.005306 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:43.189383 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.184s	user 0.123s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":602,"lbm_read_time_us":12610,"lbm_reads_lt_1ms":665,"lbm_write_time_us":31910,"lbm_writes_lt_1ms":643,"mutex_wait_us":75,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:43.190018 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=14.095187
I20260812 06:17:43.250895 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.061s	user 0.034s	sys 0.023s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23734,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:43.251385 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:43.261809 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4084,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.262218 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:43.422079 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.160s	user 0.103s	sys 0.056s 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":698,"lbm_read_time_us":11888,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26833,"lbm_writes_lt_1ms":543,"mutex_wait_us":305,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33792,"update_count":2500}
I20260812 06:17:43.422869 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:43.458698 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15191,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.459303 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:43.479894 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6257,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.480429 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:43.629128 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.149s	user 0.098s	sys 0.043s 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":86,"lbm_read_time_us":9503,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26211,"lbm_writes_lt_1ms":443,"mutex_wait_us":77,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:43.629769 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:43.664081 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14514,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.664637 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:43.677441 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.677920 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:43.806465 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.128s	user 0.088s	sys 0.040s 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":1351,"lbm_read_time_us":8362,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23703,"lbm_writes_lt_1ms":443,"mutex_wait_us":376,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":70272,"update_count":2000}
I20260812 06:17:43.807109 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:43.851816 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16253,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:43.852604 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:43.864696 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:43.865473 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:44.001066 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.135s	user 0.100s	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":493,"lbm_read_time_us":8141,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26966,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:44.001948 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:44.052541 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.050s	user 0.014s	sys 0.035s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20396,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:44.053134 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.064707 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.065356 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:44.228624 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.163s	user 0.103s	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":239,"lbm_read_time_us":11099,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27422,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:17:44.229283 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=11.118625
I20260812 06:17:44.278234 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":22024,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:44.278934 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.295984 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.017s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4425,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.296519 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.310972 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5078,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:44.311661 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushMRSOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:44.344449 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushMRSOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.033s	user 0.030s	sys 0.002s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1622,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1448,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:44.345291 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af): 448 bytes on disk
I20260812 06:17:44.345827 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:44.346392 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.357591 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.358028 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling LogGCOp(fe56dee5a2ac4079a1c065970db938af): free 108988507 bytes of WAL
I20260812 06:17:44.358242 15436 log_reader.cc:385] T fe56dee5a2ac4079a1c065970db938af: removed 11 log segments from log reader
I20260812 06:17:44.358282 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000016 (ops 75-79)
I20260812 06:17:44.358310 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000017 (ops 80-84)
I20260812 06:17:44.358373 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000018 (ops 85-89)
I20260812 06:17:44.358403 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000019 (ops 90-94)
I20260812 06:17:44.358428 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000020 (ops 95-99)
I20260812 06:17:44.358479 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000021 (ops 100-104)
I20260812 06:17:44.358516 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000022 (ops 105-109)
I20260812 06:17:44.358562 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000023 (ops 110-114)
I20260812 06:17:44.358603 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000024 (ops 115-118)
I20260812 06:17:44.358644 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000025 (ops 119-123)
I20260812 06:17:44.358683 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000026 (ops 124-128)
I20260812 06:17:44.382653 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: LogGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:44.383116 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:44.585660 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.202s	user 0.138s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877333,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":593,"lbm_read_time_us":15881,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35876,"lbm_writes_lt_1ms":643,"mutex_wait_us":39,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:17:44.588874 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=14.095187
I20260812 06:17:44.644100 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.055s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19694,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.644701 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.655354 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4135,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.655876 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:44.843477 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.187s	user 0.121s	sys 0.056s 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":214,"lbm_read_time_us":11830,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31132,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":83968,"update_count":2500}
I20260812 06:17:44.844110 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=14.095187
I20260812 06:17:44.896225 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.052s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:44.896688 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:44.917098 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.020s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:44.917757 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:45.100646 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.183s	user 0.141s	sys 0.039s 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":629,"lbm_read_time_us":14177,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31574,"lbm_writes_lt_1ms":543,"mutex_wait_us":239,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:17:45.101717 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=11.118625
I20260812 06:17:45.131017 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.029s	user 0.015s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12578,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:45.131835 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.159617 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.028s	user 0.015s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5916,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.160055 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.170565 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4068,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.171000 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:45.364001 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.193s	user 0.127s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":231,"lbm_read_time_us":12683,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29003,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:17:45.364892 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=14.095187
I20260812 06:17:45.415693 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.051s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22774,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:45.416239 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.433527 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6818,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.434190 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:45.585738 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.151s	user 0.107s	sys 0.044s 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":1142,"lbm_read_time_us":11566,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30914,"lbm_writes_lt_1ms":543,"mutex_wait_us":364,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:17:45.586486 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:45.617969 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.031s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13343,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:45.618564 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.635638 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.017s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.636220 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:45.758127 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.122s	user 0.089s	sys 0.032s 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":327,"lbm_read_time_us":8770,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22304,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":66816,"update_count":2000}
I20260812 06:17:45.758736 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=10.126437
I20260812 06:17:45.805933 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.047s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:45.806459 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.818135 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4006,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:45.818898 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushMRSOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:45.848392 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushMRSOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.029s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":170,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1465,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1476,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:45.849061 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling LogGCOp(fe56dee5a2ac4079a1c065970db938af): free 124257501 bytes of WAL
I20260812 06:17:45.849296 15436 log_reader.cc:385] T fe56dee5a2ac4079a1c065970db938af: removed 12 log segments from log reader
I20260812 06:17:45.849355 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000027 (ops 129-133)
I20260812 06:17:45.849399 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000028 (ops 134-138)
I20260812 06:17:45.849452 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000029 (ops 139-143)
I20260812 06:17:45.849496 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000030 (ops 144-148)
I20260812 06:17:45.849534 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000031 (ops 149-152)
I20260812 06:17:45.849571 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000032 (ops 153-157)
I20260812 06:17:45.849607 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000033 (ops 158-162)
I20260812 06:17:45.849646 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000034 (ops 163-167)
I20260812 06:17:45.849684 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000035 (ops 168-172)
I20260812 06:17:45.849722 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000036 (ops 173-177)
I20260812 06:17:45.849761 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000037 (ops 178-182)
I20260812 06:17:45.849798 15436 log.cc:1079] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/fe56dee5a2ac4079a1c065970db938af/wal-000000038 (ops 183-187)
I20260812 06:17:45.875838 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: LogGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:45.876250 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=3.181125
I20260812 06:17:45.891589 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.015s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:45.892113 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:45.905671 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5077,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:45.906126 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:46.087786 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.181s	user 0.127s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":240,"lbm_read_time_us":12701,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34984,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":85,"threads_started":1,"update_count":3000}
I20260812 06:17:46.088595 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=14.095187
I20260812 06:17:46.141722 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.053s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22756,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:46.142360 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af): perf score=2.188937
I20260812 06:17:46.153687 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: FlushDeltaMemStoresOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4162,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:46.154335 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af): 462 bytes on disk
I20260812 06:17:46.155161 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: UndoDeltaBlockGCOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":119,"lbm_reads_lt_1ms":4}
I20260812 06:17:46.155897 15543 maintenance_manager.cc:419] P 8979fcc73696495baceeb0dac0a400af: Scheduling MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af): perf score=1.000000
I20260812 06:17:46.188930 15288 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.943s	user 1.814s	sys 0.152s
I20260812 06:17:46.244706 15288 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.055s	user 0.002s	sys 0.000s
I20260812 06:17:46.245357 15288 tablet_server.cc:179] TabletServer@127.14.238.1:0 shutting down...
I20260812 06:17:46.288667 15436 maintenance_manager.cc:643] P 8979fcc73696495baceeb0dac0a400af: MajorDeltaCompactionOp(fe56dee5a2ac4079a1c065970db938af) complete. Timing: real 0.132s	user 0.101s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":502,"lbm_read_time_us":11774,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25613,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":43904,"update_count":2500}
I20260812 06:17:46.289448 15288 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:46.289839 15288 tablet_replica.cc:333] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af: stopping tablet replica
I20260812 06:17:46.290077 15288 raft_consensus.cc:2243] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:46.298763 15288 raft_consensus.cc:2272] T fe56dee5a2ac4079a1c065970db938af P 8979fcc73696495baceeb0dac0a400af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:46.314713 15288 tablet_server.cc:196] TabletServer@127.14.238.1:0 shutdown complete.
I20260812 06:17:46.337509 15288 master.cc:562] Master@127.14.238.62:33287 shutting down...
I20260812 06:17:46.342214 15288 raft_consensus.cc:2243] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:46.342445 15288 raft_consensus.cc:2272] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:46.342545 15288 tablet_replica.cc:333] T 00000000000000000000000000000000 P df610ca1bc3746398d9bb74c6d899c0a: stopping tablet replica
I20260812 06:17:46.355541 15288 master.cc:584] Master@127.14.238.62:33287 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5498 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:46.447011 15288 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.14.238.62:38805
I20260812 06:17:46.447476 15288 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.449725 15589 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:17:46.449831 15288 server_base.cc:1061] running on GCE node
W20260812 06:17:46.449842 15590 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:17:46.449790 15595 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:17:46.450178 15288 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.450222 15288 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:17:46.450238 15288 hybrid_clock.cc:648] HybridClock initialized: now 1786515466450238 us; error 0 us; skew 500 ppm
I20260812 06:17:46.451078 15288 webserver.cc:533] Webserver started at http://127.14.238.62:36049/ using document root <none> and password file <none>
I20260812 06:17:46.451251 15288 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.451319 15288 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.451486 15288 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.451900 15288 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/master-0-root/instance:
uuid: "12f5a891b63b44abb7f5c88d2caf5200"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-c12x"
I20260812 06:17:46.453450 15288 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:46.454422 15602 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:17:46.454703 15288 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:46.454797 15288 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/master-0-root
uuid: "12f5a891b63b44abb7f5c88d2caf5200"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-c12x"
I20260812 06:17:46.454869 15288 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-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:17:46.469637 15288 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.470069 15288 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.474447 15288 rpc_server.cc:307] RPC server started. Bound to: 127.14.238.62:38805
I20260812 06:17:46.475812 15684 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.238.62:38805 every 8 connection(s)
I20260812 06:17:46.480360 15686 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:17:46.486224 15686 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: Bootstrap starting.
I20260812 06:17:46.487156 15686 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.488416 15686 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: No bootstrap required, opened a new log
I20260812 06:17:46.488866 15686 raft_consensus.cc:359] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER }
I20260812 06:17:46.488960 15686 raft_consensus.cc:385] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.488983 15686 raft_consensus.cc:740] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 12f5a891b63b44abb7f5c88d2caf5200, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.489184 15686 consensus_queue.cc:260] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [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: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER }
I20260812 06:17:46.489260 15686 raft_consensus.cc:399] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.489315 15686 raft_consensus.cc:493] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.489375 15686 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.490123 15686 raft_consensus.cc:515] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER }
I20260812 06:17:46.490269 15686 leader_election.cc:304] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [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: 12f5a891b63b44abb7f5c88d2caf5200; no voters: 
I20260812 06:17:46.490505 15686 leader_election.cc:290] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.490715 15692 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.490950 15692 raft_consensus.cc:697] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 1 LEADER]: Becoming Leader. State: Replica: 12f5a891b63b44abb7f5c88d2caf5200, State: Running, Role: LEADER
I20260812 06:17:46.491060 15686 sys_catalog.cc:565] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:46.491109 15692 consensus_queue.cc:237] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [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: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER }
I20260812 06:17:46.492349 15693 sys_catalog.cc:455] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "12f5a891b63b44abb7f5c88d2caf5200" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER } }
I20260812 06:17:46.492445 15693 sys_catalog.cc:458] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:46.493098 15694 sys_catalog.cc:455] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 12f5a891b63b44abb7f5c88d2caf5200. Latest consensus state: current_term: 1 leader_uuid: "12f5a891b63b44abb7f5c88d2caf5200" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "12f5a891b63b44abb7f5c88d2caf5200" member_type: VOTER } }
I20260812 06:17:46.493269 15288 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:46.493495 15694 sys_catalog.cc:458] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [sys.catalog]: This master's current role is: LEADER
W20260812 06:17:46.493800 15714 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:46.493860 15714 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:46.493940 15706 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:46.494628 15706 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:46.496660 15706 catalog_manager.cc:1383] Generated new cluster ID: 5583d683d31840b7a6fd1e41ca3bdec7
I20260812 06:17:46.496718 15706 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:46.516496 15706 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:46.517081 15706 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:46.531349 15706 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: Generated new TSK 0
I20260812 06:17:46.531638 15706 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:46.558478 15288 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:46.560994 15717 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:17:46.561162 15718 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:17:46.561192 15720 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:17:46.561229 15288 server_base.cc:1061] running on GCE node
I20260812 06:17:46.561686 15288 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:46.561736 15288 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:17:46.561751 15288 hybrid_clock.cc:648] HybridClock initialized: now 1786515466561752 us; error 0 us; skew 500 ppm
I20260812 06:17:46.562803 15288 webserver.cc:533] Webserver started at http://127.14.238.1:37205/ using document root <none> and password file <none>
I20260812 06:17:46.563027 15288 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:46.563102 15288 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:46.563187 15288 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:46.563841 15288 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/instance:
uuid: "6dc7394b185a4db5be945ed91282dac3"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-c12x"
I20260812 06:17:46.565459 15288 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:46.566509 15728 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:17:46.566825 15288 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:46.566937 15288 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root
uuid: "6dc7394b185a4db5be945ed91282dac3"
format_stamp: "Formatted at 2026-08-12 06:17:46 on dist-test-slave-c12x"
I20260812 06:17:46.567023 15288 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-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:17:46.577335 15288 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:46.577829 15288 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:46.578179 15288 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:46.578698 15288 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:46.578760 15288 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.578822 15288 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:46.578868 15288 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:46.583841 15288 rpc_server.cc:307] RPC server started. Bound to: 127.14.238.1:35871
I20260812 06:17:46.584224 15831 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.14.238.1:35871 every 8 connection(s)
I20260812 06:17:46.593724 15833 heartbeater.cc:344] Connected to a master server at 127.14.238.62:38805
I20260812 06:17:46.593879 15833 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:46.594125 15833 heartbeater.cc:507] Master 127.14.238.62:38805 requested a full tablet report, sending...
I20260812 06:17:46.594884 15622 ts_manager.cc:194] Registered new tserver with Master: 6dc7394b185a4db5be945ed91282dac3 (127.14.238.1:35871)
I20260812 06:17:46.595739 15288 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01124557s
I20260812 06:17:46.595745 15622 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:33638
I20260812 06:17:46.603358 15622 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:33650:
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:17:46.613284 15772 tablet_service.cc:1511] Processing CreateTablet for tablet b34f91bbeab144a09fdc455f9e437e54 (DEFAULT_TABLE table=heavy-update-compaction-test [id=df535ac4d6804c9f8e6d9f716237cc3a]), partition=
I20260812 06:17:46.613569 15772 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b34f91bbeab144a09fdc455f9e437e54. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:46.615885 15854 tablet_bootstrap.cc:492] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Bootstrap starting.
I20260812 06:17:46.616926 15854 tablet_bootstrap.cc:654] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:46.618115 15854 tablet_bootstrap.cc:492] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: No bootstrap required, opened a new log
I20260812 06:17:46.618257 15854 ts_tablet_manager.cc:1403] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:46.618741 15854 raft_consensus.cc:359] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc7394b185a4db5be945ed91282dac3" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 35871 } }
I20260812 06:17:46.618862 15854 raft_consensus.cc:385] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:46.618911 15854 raft_consensus.cc:740] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6dc7394b185a4db5be945ed91282dac3, State: Initialized, Role: FOLLOWER
I20260812 06:17:46.619094 15854 consensus_queue.cc:260] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [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: "6dc7394b185a4db5be945ed91282dac3" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 35871 } }
I20260812 06:17:46.619205 15854 raft_consensus.cc:399] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:46.619256 15854 raft_consensus.cc:493] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:46.619313 15854 raft_consensus.cc:3060] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:46.620213 15854 raft_consensus.cc:515] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc7394b185a4db5be945ed91282dac3" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 35871 } }
I20260812 06:17:46.620383 15854 leader_election.cc:304] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [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: 6dc7394b185a4db5be945ed91282dac3; no voters: 
I20260812 06:17:46.620613 15854 leader_election.cc:290] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:46.620877 15857 raft_consensus.cc:2804] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:46.620965 15854 ts_tablet_manager.cc:1434] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:46.621011 15857 raft_consensus.cc:697] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 1 LEADER]: Becoming Leader. State: Replica: 6dc7394b185a4db5be945ed91282dac3, State: Running, Role: LEADER
I20260812 06:17:46.621039 15833 heartbeater.cc:499] Master 127.14.238.62:38805 was elected leader, sending a full tablet report...
I20260812 06:17:46.621160 15857 consensus_queue.cc:237] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [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: "6dc7394b185a4db5be945ed91282dac3" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 35871 } }
I20260812 06:17:46.622682 15622 catalog_manager.cc:5719] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 6dc7394b185a4db5be945ed91282dac3 (127.14.238.1). New cstate: current_term: 1 leader_uuid: "6dc7394b185a4db5be945ed91282dac3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc7394b185a4db5be945ed91282dac3" member_type: VOTER last_known_addr { host: "127.14.238.1" port: 35871 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:46.682425 15288 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.018s	sys 0.004s
I20260812 06:17:46.835107 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54): perf score=19.054940
I20260812 06:17:47.008114 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.173s	user 0.129s	sys 0.043s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":144,"dirs.run_cpu_time_us":407,"dirs.run_wall_time_us":936,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42730,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:47.008975 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling LogGCOp(b34f91bbeab144a09fdc455f9e437e54): free 20743831 bytes of WAL
I20260812 06:17:47.009305 15739 log_reader.cc:385] T b34f91bbeab144a09fdc455f9e437e54: removed 2 log segments from log reader
I20260812 06:17:47.009388 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000001 (ops 1-6)
I20260812 06:17:47.009446 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000002 (ops 7-11)
I20260812 06:17:47.016131 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: LogGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:17:47.016688 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:47.034044 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.034631 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54): 16411395 bytes on disk
I20260812 06:17:47.035231 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54) 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:17:47.035774 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:47.187366 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.151s	user 0.108s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":458,"lbm_read_time_us":11087,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25287,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":328,"threads_started":5,"update_count":2000}
I20260812 06:17:47.188098 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:47.238202 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.050s	user 0.017s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18054,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.238821 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:47.251965 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.252557 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:47.411288 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.159s	user 0.098s	sys 0.060s 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":205,"lbm_read_time_us":11350,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27096,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:17:47.411902 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:47.461617 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.050s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17887,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.462306 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:47.478691 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.479418 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:47.629024 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.148s	user 0.104s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":10386,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25451,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2000}
I20260812 06:17:47.629745 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:47.676015 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.046s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.676627 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:47.688549 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.689114 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:47.812111 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.123s	user 0.090s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":971,"lbm_read_time_us":8545,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23133,"lbm_writes_lt_1ms":443,"mutex_wait_us":124,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:47.812829 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:47.854561 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.042s	user 0.029s	sys 0.004s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15732,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:47.855146 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:47.871222 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6127,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:47.872099 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:48.007535 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.135s	user 0.109s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":409,"lbm_read_time_us":8760,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26445,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":63104,"update_count":2000}
I20260812 06:17:48.008064 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:48.060248 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.052s	user 0.031s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20347,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.060864 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:48.072080 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.072551 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:48.240679 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.168s	user 0.112s	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":13042,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26409,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:48.243620 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:48.291409 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23239,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:48.292034 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:48.304004 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.304646 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:48.334236 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1269,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1387,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:48.334812 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling LogGCOp(b34f91bbeab144a09fdc455f9e437e54): free 112239359 bytes of WAL
I20260812 06:17:48.335022 15739 log_reader.cc:385] T b34f91bbeab144a09fdc455f9e437e54: removed 11 log segments from log reader
I20260812 06:17:48.335080 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000003 (ops 12-16)
I20260812 06:17:48.335134 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000004 (ops 17-21)
I20260812 06:17:48.335187 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000005 (ops 22-26)
I20260812 06:17:48.335227 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000006 (ops 27-31)
I20260812 06:17:48.335263 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000007 (ops 32-36)
I20260812 06:17:48.335300 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000008 (ops 37-41)
I20260812 06:17:48.335337 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000009 (ops 42-46)
I20260812 06:17:48.335383 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000010 (ops 47-51)
I20260812 06:17:48.335420 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000011 (ops 52-56)
I20260812 06:17:48.335489 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000012 (ops 57-60)
I20260812 06:17:48.335525 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000013 (ops 61-65)
I20260812 06:17:48.359817 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: LogGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:48.360201 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=3.181125
I20260812 06:17:48.380983 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.021s	user 0.009s	sys 0.010s Metrics: {"bytes_written":4512904,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:48.381484 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:48.392297 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4374,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:48.392727 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54): 447 bytes on disk
I20260812 06:17:48.393182 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:48.393617 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:48.586870 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.193s	user 0.111s	sys 0.080s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":563,"lbm_read_time_us":14290,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30183,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:17:48.587358 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:48.652637 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.065s	user 0.026s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19558,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.653838 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:48.666317 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.666800 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:48.857298 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.190s	user 0.122s	sys 0.055s 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":221,"lbm_read_time_us":13456,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29193,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:17:48.857905 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:48.912142 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.054s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":20632,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:48.912781 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:48.936520 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.024s	user 0.007s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:48.937124 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:49.122126 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.185s	user 0.116s	sys 0.069s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1402,"lbm_read_time_us":12703,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30677,"lbm_writes_lt_1ms":543,"mutex_wait_us":113,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:49.122792 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:49.177024 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.054s	user 0.045s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23967,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.177561 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:49.190125 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.190582 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:49.392627 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.202s	user 0.143s	sys 0.048s 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":876,"lbm_read_time_us":11574,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31762,"lbm_writes_lt_1ms":543,"mutex_wait_us":87,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2500}
I20260812 06:17:49.393538 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:49.452442 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.058s	user 0.015s	sys 0.036s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":22038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:49.452965 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:49.469925 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6352,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.470402 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:49.633003 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.162s	user 0.107s	sys 0.050s 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":850,"lbm_read_time_us":12673,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31660,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:17:49.633587 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=11.118625
I20260812 06:17:49.667734 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.034s	user 0.020s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14589,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:49.668560 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:49.685395 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6515,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.685897 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:49.812177 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.126s	user 0.099s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":481,"lbm_read_time_us":7616,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24549,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:17:49.812790 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=10.126437
I20260812 06:17:49.856169 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.043s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15547,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:49.856742 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:49.868536 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:49.869081 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:49.904425 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1434,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1920,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:49.905223 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling LogGCOp(b34f91bbeab144a09fdc455f9e437e54): free 121006437 bytes of WAL
I20260812 06:17:49.905504 15739 log_reader.cc:385] T b34f91bbeab144a09fdc455f9e437e54: removed 12 log segments from log reader
I20260812 06:17:49.905580 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000014 (ops 66-70)
I20260812 06:17:49.905642 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000015 (ops 71-75)
I20260812 06:17:49.905706 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000016 (ops 76-80)
I20260812 06:17:49.905766 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000017 (ops 81-85)
I20260812 06:17:49.905810 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000018 (ops 86-90)
I20260812 06:17:49.905857 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000019 (ops 91-95)
I20260812 06:17:49.905906 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000020 (ops 96-100)
I20260812 06:17:49.905982 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000021 (ops 101-105)
I20260812 06:17:49.906047 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000022 (ops 106-110)
I20260812 06:17:49.906095 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000023 (ops 111-114)
I20260812 06:17:49.906142 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000024 (ops 115-119)
I20260812 06:17:49.906190 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000025 (ops 120-124)
I20260812 06:17:49.935300 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: LogGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:49.936009 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54): 472 bytes on disk
I20260812 06:17:49.936686 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:17:49.937350 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=3.181125
I20260812 06:17:49.950287 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4749,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:49.950738 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling LogGCOp(b34f91bbeab144a09fdc455f9e437e54): free 11564877 bytes of WAL
I20260812 06:17:49.950946 15739 log_reader.cc:385] T b34f91bbeab144a09fdc455f9e437e54: removed 1 log segments from log reader
I20260812 06:17:49.950989 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000026 (ops 125-128)
I20260812 06:17:49.953184 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: LogGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:49.953488 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:49.964747 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3613,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:49.965448 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:50.153465 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.188s	user 0.152s	sys 0.031s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1253,"lbm_read_time_us":12557,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39253,"lbm_writes_lt_1ms":643,"mutex_wait_us":755,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3840,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:17:50.154090 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:50.218492 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.064s	user 0.040s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29109,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.219060 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:50.230329 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.230881 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:50.389263 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.158s	user 0.108s	sys 0.046s 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":828,"lbm_read_time_us":10087,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30781,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:50.390548 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=12.110812
I20260812 06:17:50.430145 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.039s	user 0.020s	sys 0.016s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":17301,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:17:50.430898 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:50.451916 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.021s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3282160,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:17:50.452365 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:50.462945 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3888,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:50.463532 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:50.653009 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.189s	user 0.136s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774773,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":604,"lbm_read_time_us":13090,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31711,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":78464,"update_count":2500}
I20260812 06:17:50.653602 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:50.718736 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.065s	user 0.042s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25669,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.719261 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:50.730175 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.730630 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:50.916006 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.185s	user 0.100s	sys 0.079s 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":998,"lbm_read_time_us":12170,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31939,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:17:50.916749 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:50.980813 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.064s	user 0.028s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20630,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:50.981319 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:50.992031 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:50.992509 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:51.166839 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.174s	user 0.134s	sys 0.040s 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":204,"lbm_read_time_us":12766,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28158,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:17:51.167649 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=11.118625
I20260812 06:17:51.203661 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.036s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15319,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:51.204428 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:51.229007 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.024s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5041,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:51.229702 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:51.247498 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.018s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.248158 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:51.436086 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.188s	user 0.112s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774801,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":443,"lbm_read_time_us":13268,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29531,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33152,"update_count":2500}
I20260812 06:17:51.436743 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:51.490906 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.054s	user 0.038s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22211,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.491374 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:51.512709 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.021s	user 0.001s	sys 0.019s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.513263 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:51.548820 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushMRSOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.035s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":264,"dirs.run_wall_time_us":1303,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1853,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:51.549497 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling LogGCOp(b34f91bbeab144a09fdc455f9e437e54): free 129320730 bytes of WAL
I20260812 06:17:51.549715 15739 log_reader.cc:385] T b34f91bbeab144a09fdc455f9e437e54: removed 13 log segments from log reader
I20260812 06:17:51.549758 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000027 (ops 129-133)
I20260812 06:17:51.549788 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000028 (ops 134-138)
I20260812 06:17:51.549854 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000029 (ops 139-142)
I20260812 06:17:51.549888 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000030 (ops 143-147)
I20260812 06:17:51.549929 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000031 (ops 148-152)
I20260812 06:17:51.549995 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000032 (ops 153-157)
I20260812 06:17:51.550034 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000033 (ops 158-162)
I20260812 06:17:51.550076 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000034 (ops 163-167)
I20260812 06:17:51.550113 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000035 (ops 168-172)
I20260812 06:17:51.550151 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000036 (ops 173-177)
I20260812 06:17:51.550190 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000037 (ops 178-182)
I20260812 06:17:51.550230 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000038 (ops 183-186)
I20260812 06:17:51.550269 15739 log.cc:1079] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: Deleting log segment in path: /tmp/dist-test-taskjQ0R8W/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515460937893-15288-0/minicluster-data/ts-0-root/wals/b34f91bbeab144a09fdc455f9e437e54/wal-000000039 (ops 187-191)
I20260812 06:17:51.576375 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: LogGCOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:51.576807 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:51.594615 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4738,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.595041 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54): 493 bytes on disk
I20260812 06:17:51.595425 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: UndoDeltaBlockGCOp(b34f91bbeab144a09fdc455f9e437e54) 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:17:51.595975 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=2.188937
I20260812 06:17:51.606712 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3959,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:51.607494 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:51.820842 15288 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.138s	user 1.977s	sys 0.134s
I20260812 06:17:51.840607 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.233s	user 0.143s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":17083,"lbm_reads_lt_1ms":770,"lbm_write_time_us":41201,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:17:51.841342 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54): perf score=14.095187
I20260812 06:17:51.876158 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: FlushDeltaMemStoresOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":16284,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:51.876821 15835 maintenance_manager.cc:419] P 6dc7394b185a4db5be945ed91282dac3: Scheduling MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54): perf score=1.000000
I20260812 06:17:51.938885 15288 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.118s	user 0.001s	sys 0.000s
I20260812 06:17:51.939410 15288 tablet_server.cc:179] TabletServer@127.14.238.1:0 shutting down...
I20260812 06:17:52.017707 15739 maintenance_manager.cc:643] P 6dc7394b185a4db5be945ed91282dac3: MajorDeltaCompactionOp(b34f91bbeab144a09fdc455f9e437e54) complete. Timing: real 0.141s	user 0.084s	sys 0.056s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672161,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":462,"lbm_read_time_us":9672,"lbm_reads_lt_1ms":467,"lbm_write_time_us":31464,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":424576,"update_count":2000}
I20260812 06:17:52.018607 15288 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:52.018857 15288 tablet_replica.cc:333] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3: stopping tablet replica
I20260812 06:17:52.019021 15288 raft_consensus.cc:2243] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.019197 15288 raft_consensus.cc:2272] T b34f91bbeab144a09fdc455f9e437e54 P 6dc7394b185a4db5be945ed91282dac3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.023536 15288 tablet_server.cc:196] TabletServer@127.14.238.1:0 shutdown complete.
I20260812 06:17:52.061388 15288 master.cc:562] Master@127.14.238.62:38805 shutting down...
I20260812 06:17:52.064867 15288 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:52.065032 15288 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:52.065085 15288 tablet_replica.cc:333] T 00000000000000000000000000000000 P 12f5a891b63b44abb7f5c88d2caf5200: stopping tablet replica
I20260812 06:17:52.077811 15288 master.cc:584] Master@127.14.238.62:38805 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5719 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11219 ms total)

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