[==========] 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:17.583011 28399 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.187.254:36013
I20260812 06:17:17.583942 28399 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:17.584532 28399 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:17.590463 28399 server_base.cc:1061] running on GCE node
W20260812 06:17:17.590585 28412 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.590598 28406 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:17.590795 28409 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:17.591246 28399 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.591333 28399 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:17.591361 28399 hybrid_clock.cc:648] HybridClock initialized: now 1786515437591360 us; error 0 us; skew 500 ppm
I20260812 06:17:17.592993 28399 webserver.cc:533] Webserver started at http://127.27.187.254:46509/ using document root <none> and password file <none>
I20260812 06:17:17.593477 28399 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.593530 28399 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.593711 28399 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.595224 28399 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/master-0-root/instance:
uuid: "6c934a452e614cf995a45c2d77c9d2e1"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-xt4k"
I20260812 06:17:17.598443 28399 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:17.600448 28421 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:17.601434 28399 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:17.601552 28399 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/master-0-root
uuid: "6c934a452e614cf995a45c2d77c9d2e1"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-xt4k"
I20260812 06:17:17.601639 28399 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-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:17.622979 28399 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.623669 28399 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:17.623831 28399 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.631422 28518 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.187.254:36013 every 8 connection(s)
I20260812 06:17:17.631419 28399 rpc_server.cc:307] RPC server started. Bound to: 127.27.187.254:36013
I20260812 06:17:17.633777 28521 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:17.639079 28521 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: Bootstrap starting.
I20260812 06:17:17.641404 28521 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.642311 28521 log.cc:826] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:17.643982 28521 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: No bootstrap required, opened a new log
I20260812 06:17:17.646718 28521 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER }
I20260812 06:17:17.646883 28521 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.646943 28521 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6c934a452e614cf995a45c2d77c9d2e1, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.647562 28521 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [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: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER }
I20260812 06:17:17.647704 28521 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.647773 28521 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.647883 28521 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.648684 28521 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER }
I20260812 06:17:17.649101 28521 leader_election.cc:304] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [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: 6c934a452e614cf995a45c2d77c9d2e1; no voters: 
I20260812 06:17:17.649382 28521 leader_election.cc:290] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.649598 28525 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.649838 28525 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 1 LEADER]: Becoming Leader. State: Replica: 6c934a452e614cf995a45c2d77c9d2e1, State: Running, Role: LEADER
I20260812 06:17:17.650229 28525 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [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: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER }
I20260812 06:17:17.650532 28521 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:17.652721 28399 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:17.652912 28526 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6c934a452e614cf995a45c2d77c9d2e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER } }
I20260812 06:17:17.653016 28527 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6c934a452e614cf995a45c2d77c9d2e1. Latest consensus state: current_term: 1 leader_uuid: "6c934a452e614cf995a45c2d77c9d2e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6c934a452e614cf995a45c2d77c9d2e1" member_type: VOTER } }
I20260812 06:17:17.653028 28526 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:17.653117 28527 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [sys.catalog]: This master's current role is: LEADER
W20260812 06:17:17.655364 28547 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:17.655473 28547 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:17.655604 28548 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:17.656631 28548 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:17.665086 28548 catalog_manager.cc:1383] Generated new cluster ID: 9ff26bbfebcb4ea495569e7105d411e8
I20260812 06:17:17.665159 28548 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:17.684479 28548 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:17.685699 28548 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:17.700248 28548 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: Generated new TSK 0
I20260812 06:17:17.701122 28548 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:17.717288 28399 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:17.719805 28556 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:17.719980 28562 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:17.720126 28555 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:17.720249 28399 server_base.cc:1061] running on GCE node
I20260812 06:17:17.720467 28399 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:17.720507 28399 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:17.720522 28399 hybrid_clock.cc:648] HybridClock initialized: now 1786515437720522 us; error 0 us; skew 500 ppm
I20260812 06:17:17.721540 28399 webserver.cc:533] Webserver started at http://127.27.187.193:42265/ using document root <none> and password file <none>
I20260812 06:17:17.721699 28399 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:17.721760 28399 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:17.721817 28399 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:17.722182 28399 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/instance:
uuid: "4f379ad19cc948f1a712d1a0f1b9a94e"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-xt4k"
I20260812 06:17:17.723613 28399 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:17.724556 28574 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:17.724805 28399 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:17.724874 28399 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root
uuid: "4f379ad19cc948f1a712d1a0f1b9a94e"
format_stamp: "Formatted at 2026-08-12 06:17:17 on dist-test-slave-xt4k"
I20260812 06:17:17.724936 28399 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-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:17.730705 28399 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:17.731101 28399 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:17.731545 28399 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:17.732328 28399 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:17.732417 28399 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.732466 28399 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:17.732528 28399 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:17.738516 28399 rpc_server.cc:307] RPC server started. Bound to: 127.27.187.193:36577
I20260812 06:17:17.738574 28680 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.187.193:36577 every 8 connection(s)
I20260812 06:17:17.748577 28683 heartbeater.cc:344] Connected to a master server at 127.27.187.254:36013
I20260812 06:17:17.748802 28683 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:17.749261 28683 heartbeater.cc:507] Master 127.27.187.254:36013 requested a full tablet report, sending...
I20260812 06:17:17.750651 28448 ts_manager.cc:194] Registered new tserver with Master: 4f379ad19cc948f1a712d1a0f1b9a94e (127.27.187.193:36577)
I20260812 06:17:17.751387 28399 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012282452s
I20260812 06:17:17.751967 28448 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51204
I20260812 06:17:17.760471 28448 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51206:
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:17.773550 28631 tablet_service.cc:1511] Processing CreateTablet for tablet edcb18ce6a964e64b999700c614ce44d (DEFAULT_TABLE table=heavy-update-compaction-test [id=0cfeecbaec2c4a398717b251eb820aec]), partition=
I20260812 06:17:17.773949 28631 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet edcb18ce6a964e64b999700c614ce44d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:17.776278 28711 tablet_bootstrap.cc:492] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Bootstrap starting.
I20260812 06:17:17.777129 28711 tablet_bootstrap.cc:654] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:17.778134 28711 tablet_bootstrap.cc:492] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: No bootstrap required, opened a new log
I20260812 06:17:17.778235 28711 ts_tablet_manager.cc:1403] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:17.778764 28711 raft_consensus.cc:359] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f379ad19cc948f1a712d1a0f1b9a94e" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 36577 } }
I20260812 06:17:17.778860 28711 raft_consensus.cc:385] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:17.778892 28711 raft_consensus.cc:740] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f379ad19cc948f1a712d1a0f1b9a94e, State: Initialized, Role: FOLLOWER
I20260812 06:17:17.779017 28711 consensus_queue.cc:260] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [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: "4f379ad19cc948f1a712d1a0f1b9a94e" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 36577 } }
I20260812 06:17:17.779101 28711 raft_consensus.cc:399] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:17.779143 28711 raft_consensus.cc:493] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:17.779191 28711 raft_consensus.cc:3060] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:17.779850 28711 raft_consensus.cc:515] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f379ad19cc948f1a712d1a0f1b9a94e" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 36577 } }
I20260812 06:17:17.779973 28711 leader_election.cc:304] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [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: 4f379ad19cc948f1a712d1a0f1b9a94e; no voters: 
I20260812 06:17:17.780153 28711 leader_election.cc:290] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:17.780254 28714 raft_consensus.cc:2804] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:17.780499 28714 raft_consensus.cc:697] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 1 LEADER]: Becoming Leader. State: Replica: 4f379ad19cc948f1a712d1a0f1b9a94e, State: Running, Role: LEADER
I20260812 06:17:17.780694 28683 heartbeater.cc:499] Master 127.27.187.254:36013 was elected leader, sending a full tablet report...
I20260812 06:17:17.780716 28714 consensus_queue.cc:237] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [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: "4f379ad19cc948f1a712d1a0f1b9a94e" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 36577 } }
I20260812 06:17:17.780500 28711 ts_tablet_manager.cc:1434] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:17.783361 28448 catalog_manager.cc:5719] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e reported cstate change: term changed from 0 to 1, leader changed from <none> to 4f379ad19cc948f1a712d1a0f1b9a94e (127.27.187.193). New cstate: current_term: 1 leader_uuid: "4f379ad19cc948f1a712d1a0f1b9a94e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f379ad19cc948f1a712d1a0f1b9a94e" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 36577 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:17.849857 28399 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.025s	sys 0.008s
I20260812 06:17:17.989717 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushMRSOp(edcb18ce6a964e64b999700c614ce44d): perf score=19.054940
I20260812 06:17:18.160671 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushMRSOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.170s	user 0.133s	sys 0.024s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":273,"delete_count":0,"dirs.queue_time_us":42,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":718,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38504,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":158,"threads_started":1,"update_count":1500}
I20260812 06:17:18.161782 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling LogGCOp(edcb18ce6a964e64b999700c614ce44d): free 20743880 bytes of WAL
I20260812 06:17:18.162096 28584 log_reader.cc:385] T edcb18ce6a964e64b999700c614ce44d: removed 2 log segments from log reader
I20260812 06:17:18.162168 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000001 (ops 1-6)
I20260812 06:17:18.162276 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000002 (ops 7-11)
I20260812 06:17:18.167187 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: LogGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:18.167562 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d): 16411399 bytes on disk
I20260812 06:17:18.168864 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":266,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.169359 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:18.188710 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.019s	user 0.013s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6497,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.189200 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:18.322947 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.134s	user 0.094s	sys 0.035s 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":355,"lbm_read_time_us":7505,"lbm_reads_lt_1ms":460,"lbm_write_time_us":21179,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":277,"threads_started":5,"update_count":2000}
I20260812 06:17:18.323624 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:18.355723 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.032s	user 0.014s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13841,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.356140 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:18.369446 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.369969 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:18.494181 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.124s	user 0.104s	sys 0.020s 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":274,"lbm_read_time_us":8371,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23348,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2000}
I20260812 06:17:18.494671 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:18.534569 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.040s	user 0.029s	sys 0.001s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13987,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.535115 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:18.544962 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3668,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.545466 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:18.670169 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.125s	user 0.094s	sys 0.028s 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":366,"lbm_read_time_us":9769,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22799,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:18.670680 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:18.715157 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.044s	user 0.009s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13854,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.715706 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:18.730449 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5503,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.730974 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:18.866439 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.135s	user 0.098s	sys 0.037s 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":255,"lbm_read_time_us":11300,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21187,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:17:18.867317 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:18.909191 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.042s	user 0.018s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13097,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:18.909703 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:18.924795 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.925401 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.044643 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.119s	user 0.098s	sys 0.020s 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":755,"lbm_read_time_us":7990,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23310,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:19.045169 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:19.084514 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.039s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16253,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.084992 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:19.094946 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.095388 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.212904 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.117s	user 0.085s	sys 0.032s 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":744,"lbm_read_time_us":8091,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21955,"lbm_writes_lt_1ms":443,"mutex_wait_us":82,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2000}
I20260812 06:17:19.213400 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:19.255455 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.042s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15989,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.255942 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:19.265677 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.266074 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushMRSOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.304692 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushMRSOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.038s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1281,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1388,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:19.305619 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling LogGCOp(edcb18ce6a964e64b999700c614ce44d): free 112239310 bytes of WAL
I20260812 06:17:19.305864 28584 log_reader.cc:385] T edcb18ce6a964e64b999700c614ce44d: removed 11 log segments from log reader
I20260812 06:17:19.305912 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000003 (ops 12-16)
I20260812 06:17:19.305955 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000004 (ops 17-21)
I20260812 06:17:19.305980 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000005 (ops 22-26)
I20260812 06:17:19.306005 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000006 (ops 27-31)
I20260812 06:17:19.306027 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000007 (ops 32-36)
I20260812 06:17:19.306051 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000008 (ops 37-40)
I20260812 06:17:19.306072 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000009 (ops 41-45)
I20260812 06:17:19.306103 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000010 (ops 46-50)
I20260812 06:17:19.306142 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000011 (ops 51-55)
I20260812 06:17:19.306167 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000012 (ops 56-60)
I20260812 06:17:19.306198 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000013 (ops 61-65)
I20260812 06:17:19.327360 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: LogGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:17:19.327839 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d): 447 bytes on disk
I20260812 06:17:19.328277 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.328833 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=3.181125
I20260812 06:17:19.345880 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.017s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.346331 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:19.355443 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3338,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.355954 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.548969 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.193s	user 0.118s	sys 0.075s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":407,"lbm_read_time_us":13107,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31889,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:17:19.550971 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:19.589509 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.038s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16733,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.590116 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.711719 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.121s	user 0.105s	sys 0.016s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":286,"lbm_read_time_us":7768,"lbm_reads_lt_1ms":467,"lbm_write_time_us":20706,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:19.712198 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:19.745867 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.033s	user 0.027s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13222,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.746335 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:19.761315 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5499,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.761801 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:19.880705 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.119s	user 0.090s	sys 0.028s 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":552,"lbm_read_time_us":8512,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23297,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":83712,"update_count":2000}
I20260812 06:17:19.881191 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:19.919911 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.039s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12945,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:19.920485 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:19.935601 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5574,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.936051 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.059729 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.124s	user 0.103s	sys 0.020s 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":622,"lbm_read_time_us":8240,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23129,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:20.060189 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:20.097644 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.037s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15218,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.098117 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.108062 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3813,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.108518 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.225387 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.117s	user 0.100s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":8603,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22980,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2000}
I20260812 06:17:20.225843 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:20.269552 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.044s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15520,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.270107 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.280208 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.280654 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.421576 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.141s	user 0.091s	sys 0.050s 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":108,"lbm_read_time_us":11264,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23171,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":69120,"update_count":2000}
I20260812 06:17:20.422201 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:20.460784 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14906,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.461215 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.471071 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3679,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.471629 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.593211 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.121s	user 0.097s	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":641,"lbm_read_time_us":8115,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22419,"lbm_writes_lt_1ms":443,"mutex_wait_us":253,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.593787 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=10.126437
I20260812 06:17:20.628475 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13550,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:20.629025 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.644029 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5374,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.644665 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushMRSOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.671789 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushMRSOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":1300,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1555,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:20.672688 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling LogGCOp(edcb18ce6a964e64b999700c614ce44d): free 120553382 bytes of WAL
I20260812 06:17:20.672925 28584 log_reader.cc:385] T edcb18ce6a964e64b999700c614ce44d: removed 12 log segments from log reader
I20260812 06:17:20.672974 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000014 (ops 66-70)
I20260812 06:17:20.673012 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000015 (ops 71-74)
I20260812 06:17:20.673041 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000016 (ops 75-79)
I20260812 06:17:20.673074 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000017 (ops 80-84)
I20260812 06:17:20.673106 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000018 (ops 85-89)
I20260812 06:17:20.673139 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000019 (ops 90-94)
I20260812 06:17:20.673171 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000020 (ops 95-99)
I20260812 06:17:20.673204 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000021 (ops 100-104)
I20260812 06:17:20.673234 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000022 (ops 105-108)
I20260812 06:17:20.673265 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000023 (ops 109-113)
I20260812 06:17:20.673296 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000024 (ops 114-118)
I20260812 06:17:20.673327 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000025 (ops 119-123)
I20260812 06:17:20.695520 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: LogGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:20.695945 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d): 472 bytes on disk
I20260812 06:17:20.696446 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.697029 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=3.181125
I20260812 06:17:20.710186 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.710644 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.723755 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.013s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4725,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.724269 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:20.904605 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.180s	user 0.144s	sys 0.023s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2142,"lbm_read_time_us":10759,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34037,"lbm_writes_lt_1ms":643,"mutex_wait_us":1504,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:17:20.905107 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:20.959609 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.054s	user 0.028s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21948,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.960300 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:20.977195 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.017s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4426,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.977830 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:21.116397 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.138s	user 0.105s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":9196,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27333,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:17:21.116936 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:21.162993 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.046s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18705,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.163511 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:21.173853 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3915,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.174460 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:21.338544 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.164s	user 0.127s	sys 0.026s 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":1099,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29978,"lbm_writes_lt_1ms":543,"mutex_wait_us":430,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:17:21.339206 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:21.398638 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.059s	user 0.020s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19136,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.399142 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:21.409293 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.409739 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:21.578785 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.169s	user 0.122s	sys 0.039s 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":146,"lbm_read_time_us":12358,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27038,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":52480,"update_count":2500}
I20260812 06:17:21.579350 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:21.632874 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.053s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20552,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.633304 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:21.643201 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:21.643754 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:21.814107 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.170s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":12242,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26275,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:17:21.814703 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:21.877678 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.063s	user 0.027s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22840,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:21.878214 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:21.888713 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.010s	user 0.002s	sys 0.008s 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:21.889132 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:22.055555 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.166s	user 0.130s	sys 0.036s 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":141,"lbm_read_time_us":11393,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28456,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:22.056098 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=11.118625
I20260812 06:17:22.092259 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.036s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14731,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:22.092762 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:22.117362 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.024s	user 0.008s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:22.117982 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:22.132185 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5183,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.132714 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushMRSOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:22.181380 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushMRSOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.048s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":168,"dirs.run_wall_time_us":1103,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1676,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:22.182094 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling LogGCOp(edcb18ce6a964e64b999700c614ce44d): free 141338654 bytes of WAL
I20260812 06:17:22.182310 28584 log_reader.cc:385] T edcb18ce6a964e64b999700c614ce44d: removed 14 log segments from log reader
I20260812 06:17:22.182355 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000026 (ops 124-128)
I20260812 06:17:22.182400 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000027 (ops 129-133)
I20260812 06:17:22.182432 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000028 (ops 134-138)
I20260812 06:17:22.182457 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000029 (ops 139-142)
I20260812 06:17:22.182487 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000030 (ops 143-147)
I20260812 06:17:22.182520 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000031 (ops 148-152)
I20260812 06:17:22.182554 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000032 (ops 153-157)
I20260812 06:17:22.182585 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000033 (ops 158-162)
I20260812 06:17:22.182615 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000034 (ops 163-167)
I20260812 06:17:22.182646 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000035 (ops 168-172)
I20260812 06:17:22.182677 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000036 (ops 173-177)
I20260812 06:17:22.182749 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000037 (ops 178-182)
I20260812 06:17:22.182793 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000038 (ops 183-186)
I20260812 06:17:22.182849 28584 log.cc:1079] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/edcb18ce6a964e64b999700c614ce44d/wal-000000039 (ops 187-191)
I20260812 06:17:22.207827 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: LogGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:22.208370 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=3.181125
I20260812 06:17:22.228058 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.020s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6497,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:22.228570 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=2.188937
I20260812 06:17:22.237583 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3138,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:22.238214 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:22.416244 28399 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.566s	user 1.698s	sys 0.136s
I20260812 06:17:22.437994 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.200s	user 0.140s	sys 0.058s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":14328,"lbm_reads_lt_1ms":771,"lbm_write_time_us":32362,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3500}
I20260812 06:17:22.438596 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d): 492 bytes on disk
I20260812 06:17:22.439009 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: UndoDeltaBlockGCOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:22.439667 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d): perf score=14.095187
I20260812 06:17:22.471740 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: FlushDeltaMemStoresOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.472244 28685 maintenance_manager.cc:419] P 4f379ad19cc948f1a712d1a0f1b9a94e: Scheduling MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d): perf score=1.000000
I20260812 06:17:22.533607 28399 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.117s	user 0.000s	sys 0.002s
I20260812 06:17:22.534276 28399 tablet_server.cc:179] TabletServer@127.27.187.193:0 shutting down...
I20260812 06:17:22.598853 28584 maintenance_manager.cc:643] P 4f379ad19cc948f1a712d1a0f1b9a94e: MajorDeltaCompactionOp(edcb18ce6a964e64b999700c614ce44d) complete. Timing: real 0.126s	user 0.085s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":673,"lbm_read_time_us":8800,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24885,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":273,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:22.599411 28399 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:22.599825 28399 tablet_replica.cc:333] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e: stopping tablet replica
I20260812 06:17:22.600054 28399 raft_consensus.cc:2243] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.600276 28399 raft_consensus.cc:2272] T edcb18ce6a964e64b999700c614ce44d P 4f379ad19cc948f1a712d1a0f1b9a94e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.615132 28399 tablet_server.cc:196] TabletServer@127.27.187.193:0 shutdown complete.
I20260812 06:17:22.652504 28399 master.cc:562] Master@127.27.187.254:36013 shutting down...
I20260812 06:17:22.655773 28399 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:22.655918 28399 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:22.655969 28399 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6c934a452e614cf995a45c2d77c9d2e1: stopping tablet replica
I20260812 06:17:22.668169 28399 master.cc:584] Master@127.27.187.254:36013 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5159 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:22.754271 28399 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.187.254:39449
I20260812 06:17:22.754678 28399 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:22.756538 28740 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:22.756632 28742 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:22.756634 28747 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:22.756749 28399 server_base.cc:1061] running on GCE node
I20260812 06:17:22.757091 28399 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:22.757145 28399 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:22.757162 28399 hybrid_clock.cc:648] HybridClock initialized: now 1786515442757162 us; error 0 us; skew 500 ppm
I20260812 06:17:22.757937 28399 webserver.cc:533] Webserver started at http://127.27.187.254:35767/ using document root <none> and password file <none>
I20260812 06:17:22.758085 28399 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:22.758126 28399 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:22.758183 28399 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:22.758525 28399 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/master-0-root/instance:
uuid: "0b0c8aa233de4c7fb113d12430508a6d"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-xt4k"
I20260812 06:17:22.759953 28399 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:22.761053 28755 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:22.761361 28399 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:22.761435 28399 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/master-0-root
uuid: "0b0c8aa233de4c7fb113d12430508a6d"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-xt4k"
I20260812 06:17:22.761508 28399 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-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:22.768914 28399 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:22.769285 28399 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:22.773288 28399 rpc_server.cc:307] RPC server started. Bound to: 127.27.187.254:39449
I20260812 06:17:22.773313 28858 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.187.254:39449 every 8 connection(s)
I20260812 06:17:22.774111 28860 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:22.776012 28860 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d: Bootstrap starting.
I20260812 06:17:22.776825 28860 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:22.777797 28860 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d: No bootstrap required, opened a new log
I20260812 06:17:22.778180 28860 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER }
I20260812 06:17:22.778270 28860 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:22.778290 28860 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b0c8aa233de4c7fb113d12430508a6d, State: Initialized, Role: FOLLOWER
I20260812 06:17:22.778421 28860 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [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: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER }
I20260812 06:17:22.778501 28860 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:22.778539 28860 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:22.778607 28860 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:22.779250 28860 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER }
I20260812 06:17:22.779367 28860 leader_election.cc:304] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [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: 0b0c8aa233de4c7fb113d12430508a6d; no voters: 
I20260812 06:17:22.779547 28860 leader_election.cc:290] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:22.779685 28870 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:22.779943 28870 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 1 LEADER]: Becoming Leader. State: Replica: 0b0c8aa233de4c7fb113d12430508a6d, State: Running, Role: LEADER
I20260812 06:17:22.779947 28860 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:22.780092 28870 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [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: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER }
I20260812 06:17:22.780543 28875 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0b0c8aa233de4c7fb113d12430508a6d. Latest consensus state: current_term: 1 leader_uuid: "0b0c8aa233de4c7fb113d12430508a6d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER } }
I20260812 06:17:22.780529 28873 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0b0c8aa233de4c7fb113d12430508a6d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b0c8aa233de4c7fb113d12430508a6d" member_type: VOTER } }
I20260812 06:17:22.780637 28875 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:22.780680 28873 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:22.780972 28883 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:22.781966 28883 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:22.782132 28399 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:22.784359 28883 catalog_manager.cc:1383] Generated new cluster ID: aadf71b2da7a475fb90caeca543bd6da
I20260812 06:17:22.784430 28883 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:22.808845 28883 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:22.809511 28883 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:22.818795 28883 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d: Generated new TSK 0
I20260812 06:17:22.819001 28883 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:22.846916 28399 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:22.848837 28909 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:22.848883 28908 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:22.848896 28913 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:22.849155 28399 server_base.cc:1061] running on GCE node
I20260812 06:17:22.849315 28399 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:22.849349 28399 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:22.849370 28399 hybrid_clock.cc:648] HybridClock initialized: now 1786515442849369 us; error 0 us; skew 500 ppm
I20260812 06:17:22.850203 28399 webserver.cc:533] Webserver started at http://127.27.187.193:45137/ using document root <none> and password file <none>
I20260812 06:17:22.850334 28399 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:22.850376 28399 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:22.850432 28399 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:22.850777 28399 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/instance:
uuid: "76c0ef01c7d247e6b3b96e3210f5c8af"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-xt4k"
I20260812 06:17:22.852198 28399 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:22.853175 28921 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:22.853390 28399 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:22.853457 28399 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root
uuid: "76c0ef01c7d247e6b3b96e3210f5c8af"
format_stamp: "Formatted at 2026-08-12 06:17:22 on dist-test-slave-xt4k"
I20260812 06:17:22.853543 28399 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-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:22.863715 28399 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:22.864068 28399 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:22.864382 28399 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:22.864835 28399 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:22.864873 28399 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:22.864916 28399 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:22.864945 28399 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:22.868952 28399 rpc_server.cc:307] RPC server started. Bound to: 127.27.187.193:46765
I20260812 06:17:22.868979 29043 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.187.193:46765 every 8 connection(s)
I20260812 06:17:22.877565 29046 heartbeater.cc:344] Connected to a master server at 127.27.187.254:39449
I20260812 06:17:22.877687 29046 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:22.877918 29046 heartbeater.cc:507] Master 127.27.187.254:39449 requested a full tablet report, sending...
I20260812 06:17:22.878554 28787 ts_manager.cc:194] Registered new tserver with Master: 76c0ef01c7d247e6b3b96e3210f5c8af (127.27.187.193:46765)
I20260812 06:17:22.879261 28787 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57704
I20260812 06:17:22.879361 28399 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010020432s
I20260812 06:17:22.886219 28787 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57720:
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:22.894459 28976 tablet_service.cc:1511] Processing CreateTablet for tablet 6fbcb176c2994f8e899cef6cd45b6dae (DEFAULT_TABLE table=heavy-update-compaction-test [id=605d5245a4be4ef7b17844fe9ab2d6ff]), partition=
I20260812 06:17:22.894719 28976 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6fbcb176c2994f8e899cef6cd45b6dae. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:22.896706 29068 tablet_bootstrap.cc:492] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Bootstrap starting.
I20260812 06:17:22.897567 29068 tablet_bootstrap.cc:654] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:22.898605 29068 tablet_bootstrap.cc:492] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: No bootstrap required, opened a new log
I20260812 06:17:22.898684 29068 ts_tablet_manager.cc:1403] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:22.899091 29068 raft_consensus.cc:359] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76c0ef01c7d247e6b3b96e3210f5c8af" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 46765 } }
I20260812 06:17:22.899183 29068 raft_consensus.cc:385] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:22.899204 29068 raft_consensus.cc:740] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 76c0ef01c7d247e6b3b96e3210f5c8af, State: Initialized, Role: FOLLOWER
I20260812 06:17:22.899326 29068 consensus_queue.cc:260] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [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: "76c0ef01c7d247e6b3b96e3210f5c8af" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 46765 } }
I20260812 06:17:22.899411 29068 raft_consensus.cc:399] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:22.899451 29068 raft_consensus.cc:493] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:22.899498 29068 raft_consensus.cc:3060] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:22.900408 29068 raft_consensus.cc:515] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76c0ef01c7d247e6b3b96e3210f5c8af" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 46765 } }
I20260812 06:17:22.900547 29068 leader_election.cc:304] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [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: 76c0ef01c7d247e6b3b96e3210f5c8af; no voters: 
I20260812 06:17:22.900732 29068 leader_election.cc:290] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:22.900844 29073 raft_consensus.cc:2804] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:22.901038 29073 raft_consensus.cc:697] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 1 LEADER]: Becoming Leader. State: Replica: 76c0ef01c7d247e6b3b96e3210f5c8af, State: Running, Role: LEADER
I20260812 06:17:22.901063 29046 heartbeater.cc:499] Master 127.27.187.254:39449 was elected leader, sending a full tablet report...
I20260812 06:17:22.901181 29073 consensus_queue.cc:237] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [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: "76c0ef01c7d247e6b3b96e3210f5c8af" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 46765 } }
I20260812 06:17:22.901284 29068 ts_tablet_manager.cc:1434] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:17:22.902480 28787 catalog_manager.cc:5719] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af reported cstate change: term changed from 0 to 1, leader changed from <none> to 76c0ef01c7d247e6b3b96e3210f5c8af (127.27.187.193). New cstate: current_term: 1 leader_uuid: "76c0ef01c7d247e6b3b96e3210f5c8af" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "76c0ef01c7d247e6b3b96e3210f5c8af" member_type: VOTER last_known_addr { host: "127.27.187.193" port: 46765 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:22.960000 28399 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.017s	sys 0.005s
I20260812 06:17:23.119889 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=21.039315
I20260812 06:17:23.279551 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.159s	user 0.106s	sys 0.047s Metrics: {"bytes_written":12307492,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":210,"dirs.run_wall_time_us":1005,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40694,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:17:23.280262 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae): free 20743880 bytes of WAL
I20260812 06:17:23.280512 28928 log_reader.cc:385] T 6fbcb176c2994f8e899cef6cd45b6dae: removed 2 log segments from log reader
I20260812 06:17:23.280674 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000001 (ops 1-6)
I20260812 06:17:23.280735 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000002 (ops 7-11)
I20260812 06:17:23.286033 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:23.286528 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:23.301815 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5832,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.302431 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:23.461051 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.158s	user 0.119s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":489,"lbm_read_time_us":11294,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24636,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":290,"threads_started":5,"update_count":2000}
I20260812 06:17:23.461542 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae): 20513813 bytes on disk
I20260812 06:17:23.461959 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:17:23.462450 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:23.501308 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.039s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16186,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.501959 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:23.515949 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.014s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.516376 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:23.633481 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.117s	user 0.088s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1390,"lbm_read_time_us":7390,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22389,"lbm_writes_lt_1ms":443,"mutex_wait_us":527,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:23.634037 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:23.674873 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.039s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16059,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.675344 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:23.685494 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.686056 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:23.811569 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.125s	user 0.097s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":874,"lbm_read_time_us":9318,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22636,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:23.812029 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:23.868615 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.056s	user 0.026s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15876,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:23.869175 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:23.884079 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:23.884573 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.029136 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1757,"lbm_read_time_us":11273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22980,"lbm_writes_lt_1ms":443,"mutex_wait_us":614,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:24.029966 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:24.078452 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.048s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.078958 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:24.090188 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.090816 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.215548 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.125s	user 0.101s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":928,"lbm_read_time_us":8063,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25535,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":44288,"update_count":2000}
I20260812 06:17:24.216008 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:24.257956 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.042s	user 0.011s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15426,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.258435 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:24.268327 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3715,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.268940 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.387622 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.118s	user 0.090s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":600,"lbm_read_time_us":8892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22436,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1160832,"update_count":2000}
I20260812 06:17:24.388176 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=10.126437
I20260812 06:17:24.438097 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.050s	user 0.027s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17845,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:24.438673 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:24.448758 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.449213 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.478852 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.029s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1463,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1266,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:24.479568 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae): 448 bytes on disk
I20260812 06:17:24.479954 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:17:24.480487 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.633293 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.153s	user 0.115s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":9284,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24479,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:17:24.633786 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae): free 120553372 bytes of WAL
I20260812 06:17:24.634121 28928 log_reader.cc:385] T 6fbcb176c2994f8e899cef6cd45b6dae: removed 12 log segments from log reader
I20260812 06:17:24.634176 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000003 (ops 12-16)
I20260812 06:17:24.634214 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000004 (ops 17-21)
I20260812 06:17:24.634246 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000005 (ops 22-26)
I20260812 06:17:24.634310 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000006 (ops 27-31)
I20260812 06:17:24.634346 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000007 (ops 32-36)
I20260812 06:17:24.634403 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000008 (ops 37-40)
I20260812 06:17:24.634435 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000009 (ops 41-45)
I20260812 06:17:24.634476 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000010 (ops 46-50)
I20260812 06:17:24.634510 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000011 (ops 51-55)
I20260812 06:17:24.634567 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000012 (ops 56-60)
I20260812 06:17:24.634598 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000013 (ops 61-64)
I20260812 06:17:24.634651 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000014 (ops 65-69)
I20260812 06:17:24.661502 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:24.661899 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=15.087375
I20260812 06:17:24.707083 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.045s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":19566,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:24.707616 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:24.732470 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.025s	user 0.005s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4467,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:24.732959 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:24.742848 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:24.743271 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:24.935343 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.192s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918199,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":647,"lbm_read_time_us":13323,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32223,"lbm_writes_lt_1ms":643,"mutex_wait_us":292,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:24.936105 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:24.996891 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.061s	user 0.033s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21817,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:24.997346 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:25.011901 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.012476 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:25.188539 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.176s	user 0.104s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":339,"lbm_read_time_us":11691,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26152,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":28416,"update_count":2500}
I20260812 06:17:25.189095 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:25.232513 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.043s	user 0.039s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18856,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.232975 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:25.250813 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.018s	user 0.004s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.251283 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:25.424319 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.173s	user 0.096s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":908,"lbm_read_time_us":12825,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25843,"lbm_writes_lt_1ms":543,"mutex_wait_us":683,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:25.424881 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:25.471076 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.046s	user 0.039s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21029,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.471649 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:25.488030 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5568,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.488554 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:25.657650 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.169s	user 0.113s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":10252,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25927,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:17:25.658195 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:25.698930 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.040s	user 0.025s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17686,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:25.699448 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:25.711585 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4208,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:25.712190 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:25.860373 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.148s	user 0.128s	sys 0.014s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":64,"lbm_read_time_us":11109,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26645,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:17:25.861042 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=11.118625
I20260812 06:17:25.890949 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.029s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11534,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:25.891549 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:25.903855 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3660,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:25.904318 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:25.961220 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.057s	user 0.025s	sys 0.006s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":165,"dirs.run_wall_time_us":1377,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1518,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:25.962003 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae): free 124710250 bytes of WAL
I20260812 06:17:25.962283 28928 log_reader.cc:385] T 6fbcb176c2994f8e899cef6cd45b6dae: removed 12 log segments from log reader
I20260812 06:17:25.962343 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000015 (ops 70-74)
I20260812 06:17:25.962466 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000016 (ops 75-79)
I20260812 06:17:25.962508 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000017 (ops 80-84)
I20260812 06:17:25.962534 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000018 (ops 85-89)
I20260812 06:17:25.962559 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000019 (ops 90-94)
I20260812 06:17:25.962622 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000020 (ops 95-99)
I20260812 06:17:25.962657 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000021 (ops 100-104)
I20260812 06:17:25.962714 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000022 (ops 105-109)
I20260812 06:17:25.962749 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000023 (ops 110-114)
I20260812 06:17:25.962771 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000024 (ops 115-119)
I20260812 06:17:25.962815 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000025 (ops 120-124)
I20260812 06:17:25.962850 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000026 (ops 125-129)
I20260812 06:17:25.992544 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:25.993184 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=7.149875
I20260812 06:17:26.022222 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.029s	user 0.014s	sys 0.013s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":12085,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:26.022691 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae): 482 bytes on disk
I20260812 06:17:26.023110 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:17:26.023602 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:26.049041 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.025s	user 0.008s	sys 0.016s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5317,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:26.049809 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:26.270802 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.221s	user 0.149s	sys 0.060s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020729,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":238,"lbm_read_time_us":14605,"lbm_reads_lt_1ms":766,"lbm_write_time_us":37458,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5120,"thread_start_us":67,"threads_started":1,"update_count":3500}
I20260812 06:17:26.271332 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=18.063937
I20260812 06:17:26.330403 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.059s	user 0.024s	sys 0.028s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":26055,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":502,"reinsert_count":0,"update_count":2500}
I20260812 06:17:26.330911 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:26.340758 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.341205 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:26.525441 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.184s	user 0.130s	sys 0.052s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1442,"lbm_read_time_us":12714,"lbm_reads_lt_1ms":672,"lbm_write_time_us":28047,"lbm_writes_lt_1ms":643,"mutex_wait_us":1170,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:17:26.528748 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=15.087375
I20260812 06:17:26.568559 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.040s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16697069,"delete_count":0,"lbm_write_time_us":16925,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2035}
I20260812 06:17:26.570149 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:26.583993 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":5361,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:17:26.584462 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:26.746922 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.162s	user 0.113s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":325,"lbm_read_time_us":10497,"lbm_reads_lt_1ms":564,"lbm_write_time_us":25780,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:17:26.747466 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:26.802400 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.055s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19223,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:26.802989 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:26.814160 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:26.814564 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:26.978281 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.164s	user 0.106s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":10911,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25593,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":74496,"update_count":2500}
I20260812 06:17:26.978964 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:27.035401 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.056s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":20893,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.035989 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:27.046037 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3758,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.046468 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:27.216782 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.170s	user 0.110s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":101,"lbm_read_time_us":10848,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28381,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:17:27.217430 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=14.095187
I20260812 06:17:27.265671 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.045s	user 0.012s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17649,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:27.266220 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:27.289032 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.023s	user 0.011s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:27.289539 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:27.318360 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushMRSOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.029s	user 0.022s	sys 0.001s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":217,"dirs.run_wall_time_us":1195,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1364,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:27.319160 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae): free 120100641 bytes of WAL
I20260812 06:17:27.319397 28928 log_reader.cc:385] T 6fbcb176c2994f8e899cef6cd45b6dae: removed 12 log segments from log reader
I20260812 06:17:27.319458 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000027 (ops 130-134)
I20260812 06:17:27.319511 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000028 (ops 135-139)
I20260812 06:17:27.319543 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000029 (ops 140-144)
I20260812 06:17:27.319568 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000030 (ops 145-148)
I20260812 06:17:27.319599 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000031 (ops 149-153)
I20260812 06:17:27.319628 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000032 (ops 154-158)
I20260812 06:17:27.319656 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000033 (ops 159-162)
I20260812 06:17:27.319682 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000034 (ops 163-167)
I20260812 06:17:27.319713 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000035 (ops 168-172)
I20260812 06:17:27.319744 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000036 (ops 173-176)
I20260812 06:17:27.319772 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000037 (ops 177-181)
I20260812 06:17:27.319800 28928 log.cc:1079] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: Deleting log segment in path: /tmp/dist-test-taskzPDn37/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515437572413-28399-0/minicluster-data/ts-0-root/wals/6fbcb176c2994f8e899cef6cd45b6dae/wal-000000038 (ops 182-186)
I20260812 06:17:27.347008 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: LogGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.028s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:27.347443 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=3.181125
I20260812 06:17:27.366181 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.019s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3996,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:27.366652 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=2.188937
I20260812 06:17:27.375840 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3215,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:27.376462 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae): 447 bytes on disk
I20260812 06:17:27.377056 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: UndoDeltaBlockGCOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:17:27.377632 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:27.604303 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.227s	user 0.146s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020734,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2543,"lbm_read_time_us":13113,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36108,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":76,"threads_started":1,"update_count":3500}
I20260812 06:17:27.604936 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=18.063937
I20260812 06:17:27.661358 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: FlushDeltaMemStoresOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.056s	user 0.049s	sys 0.006s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":24977,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:27.661912 29047 maintenance_manager.cc:419] P 76c0ef01c7d247e6b3b96e3210f5c8af: Scheduling MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae): perf score=1.000000
I20260812 06:17:27.683805 28399 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.724s	user 1.688s	sys 0.198s
I20260812 06:17:27.757479 28399 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.073s	user 0.003s	sys 0.000s
I20260812 06:17:27.758138 28399 tablet_server.cc:179] TabletServer@127.27.187.193:0 shutting down...
I20260812 06:17:27.823673 28928 maintenance_manager.cc:643] P 76c0ef01c7d247e6b3b96e3210f5c8af: MajorDeltaCompactionOp(6fbcb176c2994f8e899cef6cd45b6dae) complete. Timing: real 0.162s	user 0.117s	sys 0.044s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815566,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":819,"lbm_read_time_us":12216,"lbm_reads_lt_1ms":563,"lbm_write_time_us":30115,"lbm_writes_lt_1ms":543,"mutex_wait_us":384,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":58880,"update_count":2500}
I20260812 06:17:27.824239 28399 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:27.824494 28399 tablet_replica.cc:333] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af: stopping tablet replica
I20260812 06:17:27.824609 28399 raft_consensus.cc:2243] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.824788 28399 raft_consensus.cc:2272] T 6fbcb176c2994f8e899cef6cd45b6dae P 76c0ef01c7d247e6b3b96e3210f5c8af [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.829753 28399 tablet_server.cc:196] TabletServer@127.27.187.193:0 shutdown complete.
I20260812 06:17:27.868749 28399 master.cc:562] Master@127.27.187.254:39449 shutting down...
I20260812 06:17:27.871505 28399 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:27.871670 28399 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:27.871732 28399 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0b0c8aa233de4c7fb113d12430508a6d: stopping tablet replica
I20260812 06:17:27.883797 28399 master.cc:584] Master@127.27.187.254:39449 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5213 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10374 ms total)

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