[==========] 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:09.601099 10595 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.88.254:34739
I20260812 06:17:09.602152 10595 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:09.602782 10595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.609321 10605 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:09.609349 10603 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:09.609463 10595 server_base.cc:1061] running on GCE node
W20260812 06:17:09.609611 10602 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:09.610170 10595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.610258 10595 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:09.610291 10595 hybrid_clock.cc:648] HybridClock initialized: now 1786515429610290 us; error 0 us; skew 500 ppm
I20260812 06:17:09.612047 10595 webserver.cc:533] Webserver started at http://127.10.88.254:35411/ using document root <none> and password file <none>
I20260812 06:17:09.612550 10595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.612607 10595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.612794 10595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.614493 10595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/master-0-root/instance:
uuid: "0fa74799dea949ecbfdeaee23d5a20e0"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-ffrd"
I20260812 06:17:09.618237 10595 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:09.620371 10612 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:09.621497 10595 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:09.621600 10595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/master-0-root
uuid: "0fa74799dea949ecbfdeaee23d5a20e0"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-ffrd"
I20260812 06:17:09.621730 10595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-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:09.640868 10595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.641682 10595 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:09.641892 10595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.649906 10708 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.88.254:34739 every 8 connection(s)
I20260812 06:17:09.649919 10595 rpc_server.cc:307] RPC server started. Bound to: 127.10.88.254:34739
I20260812 06:17:09.652622 10712 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:09.658326 10712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: Bootstrap starting.
I20260812 06:17:09.660877 10712 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.661901 10712 log.cc:826] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:09.663744 10712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: No bootstrap required, opened a new log
I20260812 06:17:09.666601 10712 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER }
I20260812 06:17:09.666774 10712 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.666817 10712 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0fa74799dea949ecbfdeaee23d5a20e0, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.667438 10712 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [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: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER }
I20260812 06:17:09.667593 10712 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.667635 10712 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.667725 10712 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.668566 10712 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER }
I20260812 06:17:09.669157 10712 leader_election.cc:304] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [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: 0fa74799dea949ecbfdeaee23d5a20e0; no voters: 
I20260812 06:17:09.669574 10712 leader_election.cc:290] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.669765 10718 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.670066 10718 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 1 LEADER]: Becoming Leader. State: Replica: 0fa74799dea949ecbfdeaee23d5a20e0, State: Running, Role: LEADER
I20260812 06:17:09.670491 10718 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [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: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER }
I20260812 06:17:09.671173 10712 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:09.672857 10719 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER } }
I20260812 06:17:09.672891 10721 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0fa74799dea949ecbfdeaee23d5a20e0. Latest consensus state: current_term: 1 leader_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0fa74799dea949ecbfdeaee23d5a20e0" member_type: VOTER } }
I20260812 06:17:09.673018 10719 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.673022 10721 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.673381 10734 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:09.673714 10595 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:09.675819 10734 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:09.680605 10734 catalog_manager.cc:1383] Generated new cluster ID: 7bb13d0633664fb693b929bd0b02104c
I20260812 06:17:09.680693 10734 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:09.701002 10734 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:09.701890 10734 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:09.716125 10734 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: Generated new TSK 0
I20260812 06:17:09.716809 10734 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:09.738415 10595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.741132 10750 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:09.741192 10753 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:09.741143 10751 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:09.741528 10595 server_base.cc:1061] running on GCE node
I20260812 06:17:09.741715 10595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.741763 10595 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:09.741786 10595 hybrid_clock.cc:648] HybridClock initialized: now 1786515429741785 us; error 0 us; skew 500 ppm
I20260812 06:17:09.742761 10595 webserver.cc:533] Webserver started at http://127.10.88.193:39625/ using document root <none> and password file <none>
I20260812 06:17:09.742931 10595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.743000 10595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.743076 10595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.743521 10595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/instance:
uuid: "6e9abe5cf8fa462184177f88d4b4b49e"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-ffrd"
I20260812 06:17:09.745399 10595 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:09.746552 10758 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:09.746858 10595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:09.746922 10595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root
uuid: "6e9abe5cf8fa462184177f88d4b4b49e"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-ffrd"
I20260812 06:17:09.747020 10595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-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:09.758883 10595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.759382 10595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.759932 10595 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:09.760775 10595 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:09.760826 10595 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.760893 10595 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:09.760987 10595 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.767658 10595 rpc_server.cc:307] RPC server started. Bound to: 127.10.88.193:43693
I20260812 06:17:09.767717 10865 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.88.193:43693 every 8 connection(s)
I20260812 06:17:09.778791 10869 heartbeater.cc:344] Connected to a master server at 127.10.88.254:34739
I20260812 06:17:09.779069 10869 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:09.779538 10869 heartbeater.cc:507] Master 127.10.88.254:34739 requested a full tablet report, sending...
I20260812 06:17:09.780982 10642 ts_manager.cc:194] Registered new tserver with Master: 6e9abe5cf8fa462184177f88d4b4b49e (127.10.88.193:43693)
I20260812 06:17:09.781068 10595 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012730071s
I20260812 06:17:09.782199 10642 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35892
I20260812 06:17:09.792912 10642 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35902:
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:09.807338 10792 tablet_service.cc:1511] Processing CreateTablet for tablet d0fe3ed0da0b4f2990fb81a4f819213c (DEFAULT_TABLE table=heavy-update-compaction-test [id=b6eccfa14b724f7da3f7199c0711bb5e]), partition=
I20260812 06:17:09.807809 10792 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet d0fe3ed0da0b4f2990fb81a4f819213c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.810227 10885 tablet_bootstrap.cc:492] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Bootstrap starting.
I20260812 06:17:09.811358 10885 tablet_bootstrap.cc:654] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.812706 10885 tablet_bootstrap.cc:492] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: No bootstrap required, opened a new log
I20260812 06:17:09.812819 10885 ts_tablet_manager.cc:1403] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:09.813364 10885 raft_consensus.cc:359] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e9abe5cf8fa462184177f88d4b4b49e" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 43693 } }
I20260812 06:17:09.813509 10885 raft_consensus.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.813547 10885 raft_consensus.cc:740] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6e9abe5cf8fa462184177f88d4b4b49e, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.813719 10885 consensus_queue.cc:260] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [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: "6e9abe5cf8fa462184177f88d4b4b49e" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 43693 } }
I20260812 06:17:09.813843 10885 raft_consensus.cc:399] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.813930 10885 raft_consensus.cc:493] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.813994 10885 raft_consensus.cc:3060] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.815317 10885 raft_consensus.cc:515] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e9abe5cf8fa462184177f88d4b4b49e" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 43693 } }
I20260812 06:17:09.815506 10885 leader_election.cc:304] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [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: 6e9abe5cf8fa462184177f88d4b4b49e; no voters: 
I20260812 06:17:09.815727 10885 leader_election.cc:290] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.815938 10888 raft_consensus.cc:2804] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.816082 10885 ts_tablet_manager.cc:1434] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.004s
I20260812 06:17:09.816265 10888 raft_consensus.cc:697] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 1 LEADER]: Becoming Leader. State: Replica: 6e9abe5cf8fa462184177f88d4b4b49e, State: Running, Role: LEADER
I20260812 06:17:09.816526 10869 heartbeater.cc:499] Master 127.10.88.254:34739 was elected leader, sending a full tablet report...
I20260812 06:17:09.816890 10888 consensus_queue.cc:237] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [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: "6e9abe5cf8fa462184177f88d4b4b49e" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 43693 } }
I20260812 06:17:09.819989 10642 catalog_manager.cc:5719] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e reported cstate change: term changed from 0 to 1, leader changed from <none> to 6e9abe5cf8fa462184177f88d4b4b49e (127.10.88.193). New cstate: current_term: 1 leader_uuid: "6e9abe5cf8fa462184177f88d4b4b49e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6e9abe5cf8fa462184177f88d4b4b49e" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 43693 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.889691 10595 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.021s	sys 0.008s
I20260812 06:17:10.019205 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=15.086190
I20260812 06:17:10.181038 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.161s	user 0.130s	sys 0.020s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":202,"delete_count":0,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":942,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39048,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":768,"thread_start_us":135,"threads_started":1,"update_count":1450}
I20260812 06:17:10.182130 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 20743880 bytes of WAL
I20260812 06:17:10.182461 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 2 log segments from log reader
I20260812 06:17:10.182543 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000001 (ops 1-6)
I20260812 06:17:10.182646 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000002 (ops 7-11)
I20260812 06:17:10.187281 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:10.187636 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): 12719214 bytes on disk
I20260812 06:17:10.188212 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.188603 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:10.210954 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.022s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.211622 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:10.377274 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.165s	user 0.132s	sys 0.033s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":225,"lbm_read_time_us":9802,"lbm_reads_lt_1ms":450,"lbm_write_time_us":29736,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":311,"threads_started":5,"update_count":1950}
I20260812 06:17:10.377921 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=10.126437
I20260812 06:17:10.431885 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.054s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19815,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.432637 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:10.447561 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.448052 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:10.644483 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.196s	user 0.159s	sys 0.021s 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":164,"lbm_read_time_us":13021,"lbm_reads_lt_1ms":472,"lbm_write_time_us":34987,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":2000}
I20260812 06:17:10.645107 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=10.126437
I20260812 06:17:10.704550 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.059s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":21464,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.705086 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:10.717875 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.013s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4543,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.718364 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:10.850286 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.132s	user 0.110s	sys 0.021s 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":876,"lbm_read_time_us":9818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25087,"lbm_writes_lt_1ms":443,"mutex_wait_us":84,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":82048,"update_count":2000}
I20260812 06:17:10.850970 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=10.126437
I20260812 06:17:10.912218 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.061s	user 0.021s	sys 0.035s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23555,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:10.912788 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:10.923696 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.924172 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:11.087340 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.163s	user 0.110s	sys 0.053s 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":973,"lbm_read_time_us":11735,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29278,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:17:11.087910 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=10.126437
I20260812 06:17:11.136304 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.048s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18887,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.136848 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.148286 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4182,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.148844 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:11.276260 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.127s	user 0.106s	sys 0.021s 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":146,"lbm_read_time_us":10479,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25799,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:11.276746 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=10.126437
I20260812 06:17:11.323786 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.047s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":21558,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.324327 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.351197 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.027s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6018,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.351642 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.362442 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4017,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.362998 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:11.523159 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.160s	user 0.121s	sys 0.038s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774806,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":445,"lbm_read_time_us":12671,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31420,"lbm_writes_lt_1ms":543,"mutex_wait_us":93,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:17:11.523695 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=11.118625
I20260812 06:17:11.572268 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.048s	user 0.016s	sys 0.029s Metrics: {"bytes_written":12717743,"delete_count":0,"lbm_write_time_us":19980,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:17:11.572925 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.594918 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.022s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":5319,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:11.595372 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.606031 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:11.606498 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:11.636237 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.030s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":275,"dirs.run_wall_time_us":1160,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1630,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:11.637166 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 112239314 bytes of WAL
I20260812 06:17:11.637419 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 11 log segments from log reader
I20260812 06:17:11.637487 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000003 (ops 12-16)
I20260812 06:17:11.637526 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000004 (ops 17-21)
I20260812 06:17:11.637552 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000005 (ops 22-26)
I20260812 06:17:11.637588 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000006 (ops 27-31)
I20260812 06:17:11.637611 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000007 (ops 32-36)
I20260812 06:17:11.637640 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000008 (ops 37-41)
I20260812 06:17:11.637662 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000009 (ops 42-46)
I20260812 06:17:11.637691 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000010 (ops 47-50)
I20260812 06:17:11.637722 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000011 (ops 51-55)
I20260812 06:17:11.637753 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000012 (ops 56-60)
I20260812 06:17:11.637780 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000013 (ops 61-65)
I20260812 06:17:11.665745 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.028s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:11.666147 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): 461 bytes on disk
I20260812 06:17:11.666651 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.667101 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=3.181125
I20260812 06:17:11.690553 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.023s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5879,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:11.691123 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 12017939 bytes of WAL
I20260812 06:17:11.691347 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 1 log segments from log reader
I20260812 06:17:11.691414 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000014 (ops 66-70)
I20260812 06:17:11.693867 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:11.694198 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.704591 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.010s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3625,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.705088 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:11.901230 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.196s	user 0.137s	sys 0.057s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979863,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1601,"lbm_read_time_us":14925,"lbm_reads_lt_1ms":775,"lbm_write_time_us":37473,"lbm_writes_lt_1ms":743,"mutex_wait_us":44,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:17:11.902172 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:11.947932 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.044s	user 0.017s	sys 0.024s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19611,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.948675 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:11.963269 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.014s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5833,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.963801 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:12.113114 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.149s	user 0.109s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":817,"lbm_read_time_us":9873,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29288,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:12.113870 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:12.161516 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.047s	user 0.031s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21059,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.162052 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:12.315757 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.153s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":79,"lbm_read_time_us":12350,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26382,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:17:12.316349 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=11.118625
I20260812 06:17:12.366328 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.050s	user 0.025s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18108,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.366950 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:12.382675 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5904,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.383215 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:12.554912 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.172s	user 0.126s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":12033,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27762,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:17:12.555549 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:12.611966 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.056s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22900,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.612496 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:12.625166 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.012s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.625892 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:12.797171 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.171s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1380,"lbm_read_time_us":11285,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34077,"lbm_writes_lt_1ms":543,"mutex_wait_us":283,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.797729 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:12.846930 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.049s	user 0.028s	sys 0.013s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19212,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.847685 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:12.860390 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4401,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.861053 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:13.011334 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.150s	user 0.116s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":10321,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31031,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:17:13.011936 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=11.118625
I20260812 06:17:13.048663 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.037s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15045,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.049283 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:13.061884 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4697,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.062424 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:13.093238 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.031s	user 0.024s	sys 0.007s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":1105,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1672,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.093928 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 108988505 bytes of WAL
I20260812 06:17:13.094146 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 11 log segments from log reader
I20260812 06:17:13.094189 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000015 (ops 71-75)
I20260812 06:17:13.094218 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000016 (ops 76-80)
I20260812 06:17:13.094278 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000017 (ops 81-85)
I20260812 06:17:13.094324 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000018 (ops 86-90)
I20260812 06:17:13.094374 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000019 (ops 91-94)
I20260812 06:17:13.094436 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000020 (ops 95-99)
I20260812 06:17:13.094473 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000021 (ops 100-104)
I20260812 06:17:13.094513 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000022 (ops 105-109)
I20260812 06:17:13.094550 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000023 (ops 110-114)
I20260812 06:17:13.094591 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000024 (ops 115-119)
I20260812 06:17:13.094632 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000025 (ops 120-124)
I20260812 06:17:13.121392 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:13.121811 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=4.173312
I20260812 06:17:13.135689 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5333393,"delete_count":0,"lbm_write_time_us":5714,"lbm_writes_lt_1ms":133,"reinsert_count":0,"update_count":650}
I20260812 06:17:13.136127 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 11564877 bytes of WAL
I20260812 06:17:13.136328 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 1 log segments from log reader
I20260812 06:17:13.136371 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000026 (ops 125-128)
I20260812 06:17:13.138732 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:13.139045 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.196750
I20260812 06:17:13.153803 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.015s	user 0.010s	sys 0.001s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:17:13.154420 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:13.331310 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.177s	user 0.150s	sys 0.027s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877304,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":487,"lbm_read_time_us":14196,"lbm_reads_lt_1ms":670,"lbm_write_time_us":34982,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:13.333132 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:13.396591 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.063s	user 0.025s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":29358,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:17:13.397156 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): 463 bytes on disk
I20260812 06:17:13.397578 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: UndoDeltaBlockGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.398154 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=3.181125
I20260812 06:17:13.412710 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.413241 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:13.423058 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3653,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.423512 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:13.600534 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.177s	user 0.144s	sys 0.032s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877210,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":635,"lbm_read_time_us":12403,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37554,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:17:13.601733 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:13.654711 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.051s	user 0.046s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21754,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.655261 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:13.671254 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6164,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.671777 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:13.840337 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.168s	user 0.126s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":11521,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32292,"lbm_writes_lt_1ms":543,"mutex_wait_us":100,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.841050 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:13.904719 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.063s	user 0.042s	sys 0.005s Metrics: {"bytes_written":16409938,"delete_count":0,"lbm_write_time_us":22841,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.905241 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:13.916499 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.917057 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:14.109526 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.192s	user 0.110s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1373,"lbm_read_time_us":14503,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33929,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:17:14.110049 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:14.175601 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.065s	user 0.032s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22835,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.176106 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:14.186985 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4338,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.187472 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:14.382401 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.195s	user 0.158s	sys 0.030s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":581,"lbm_read_time_us":15618,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32896,"lbm_writes_lt_1ms":543,"mutex_wait_us":309,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:17:14.383138 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=14.095187
I20260812 06:17:14.445794 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.062s	user 0.039s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23258,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.446341 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:14.457422 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4275,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.457911 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:14.501099 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushMRSOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.043s	user 0.025s	sys 0.005s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":292,"dirs.run_wall_time_us":1261,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:14.501884 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c): free 112692616 bytes of WAL
I20260812 06:17:14.502135 10768 log_reader.cc:385] T d0fe3ed0da0b4f2990fb81a4f819213c: removed 11 log segments from log reader
I20260812 06:17:14.502203 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000027 (ops 129-133)
I20260812 06:17:14.502254 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000028 (ops 134-138)
I20260812 06:17:14.502313 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000029 (ops 139-143)
I20260812 06:17:14.502370 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000030 (ops 144-148)
I20260812 06:17:14.502408 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000031 (ops 149-153)
I20260812 06:17:14.502449 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000032 (ops 154-158)
I20260812 06:17:14.502488 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000033 (ops 159-163)
I20260812 06:17:14.502528 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000034 (ops 164-168)
I20260812 06:17:14.502568 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000035 (ops 169-173)
I20260812 06:17:14.502607 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000036 (ops 174-178)
I20260812 06:17:14.502648 10768 log.cc:1079] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/d0fe3ed0da0b4f2990fb81a4f819213c/wal-000000037 (ops 179-183)
I20260812 06:17:14.529301 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: LogGCOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.027s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:14.529769 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=3.181125
I20260812 06:17:14.552786 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.023s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7565,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:14.553332 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:14.567765 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5468,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.568385 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:14.803615 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.235s	user 0.134s	sys 0.090s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":570,"lbm_read_time_us":18428,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40794,"lbm_writes_lt_1ms":743,"mutex_wait_us":88,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":80,"threads_started":1,"update_count":3500}
I20260812 06:17:14.804919 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=15.087375
I20260812 06:17:14.857452 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.052s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":19833,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:14.858011 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:14.869081 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4482,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.869511 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=2.188937
I20260812 06:17:14.880084 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: FlushDeltaMemStoresOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:14.880573 10870 maintenance_manager.cc:419] P 6e9abe5cf8fa462184177f88d4b4b49e: Scheduling MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c): perf score=1.000000
I20260812 06:17:14.966712 10595 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.077s	user 1.857s	sys 0.144s
I20260812 06:17:15.061404 10595 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.004s	sys 0.000s
I20260812 06:17:15.062070 10595 tablet_server.cc:179] TabletServer@127.10.88.193:0 shutting down...
I20260812 06:17:15.076509 10768 maintenance_manager.cc:643] P 6e9abe5cf8fa462184177f88d4b4b49e: MajorDeltaCompactionOp(d0fe3ed0da0b4f2990fb81a4f819213c) complete. Timing: real 0.196s	user 0.160s	sys 0.036s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":892,"lbm_read_time_us":16422,"lbm_reads_lt_1ms":669,"lbm_write_time_us":37947,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:15.077535 10595 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:15.078151 10595 tablet_replica.cc:333] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e: stopping tablet replica
I20260812 06:17:15.078403 10595 raft_consensus.cc:2243] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.078713 10595 raft_consensus.cc:2272] T d0fe3ed0da0b4f2990fb81a4f819213c P 6e9abe5cf8fa462184177f88d4b4b49e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.098395 10595 tablet_server.cc:196] TabletServer@127.10.88.193:0 shutdown complete.
I20260812 06:17:15.130729 10595 master.cc:562] Master@127.10.88.254:34739 shutting down...
I20260812 06:17:15.134370 10595 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.134577 10595 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.134666 10595 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0fa74799dea949ecbfdeaee23d5a20e0: stopping tablet replica
I20260812 06:17:15.147230 10595 master.cc:584] Master@127.10.88.254:34739 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5643 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:15.244002 10595 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.88.254:44279
I20260812 06:17:15.244400 10595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.246424 10919 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:15.246483 10916 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:15.246483 10917 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:15.246492 10595 server_base.cc:1061] running on GCE node
I20260812 06:17:15.246855 10595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.246922 10595 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:15.246946 10595 hybrid_clock.cc:648] HybridClock initialized: now 1786515435246946 us; error 0 us; skew 500 ppm
I20260812 06:17:15.247764 10595 webserver.cc:533] Webserver started at http://127.10.88.254:42311/ using document root <none> and password file <none>
I20260812 06:17:15.247951 10595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.248030 10595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.248107 10595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.248492 10595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/master-0-root/instance:
uuid: "09165c51a34949d1a7f1bf703bae6a00"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-ffrd"
I20260812 06:17:15.250049 10595 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:15.251039 10927 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:15.251314 10595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:15.251416 10595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/master-0-root
uuid: "09165c51a34949d1a7f1bf703bae6a00"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-ffrd"
I20260812 06:17:15.251503 10595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-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:15.261919 10595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.262346 10595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.266873 10595 rpc_server.cc:307] RPC server started. Bound to: 127.10.88.254:44279
I20260812 06:17:15.282297 11022 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.88.254:44279 every 8 connection(s)
I20260812 06:17:15.290292 11023 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:15.292477 11023 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00: Bootstrap starting.
I20260812 06:17:15.293427 11023 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.294523 11023 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00: No bootstrap required, opened a new log
I20260812 06:17:15.294935 11023 raft_consensus.cc:359] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER }
I20260812 06:17:15.295056 11023 raft_consensus.cc:385] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.295110 11023 raft_consensus.cc:740] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 09165c51a34949d1a7f1bf703bae6a00, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.295269 11023 consensus_queue.cc:260] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [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: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER }
I20260812 06:17:15.295362 11023 raft_consensus.cc:399] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.295413 11023 raft_consensus.cc:493] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.295469 11023 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.296209 11023 raft_consensus.cc:515] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER }
I20260812 06:17:15.296367 11023 leader_election.cc:304] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [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: 09165c51a34949d1a7f1bf703bae6a00; no voters: 
I20260812 06:17:15.296591 11023 leader_election.cc:290] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.296934 11028 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.297134 11023 sys_catalog.cc:565] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:15.297243 11028 raft_consensus.cc:697] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 1 LEADER]: Becoming Leader. State: Replica: 09165c51a34949d1a7f1bf703bae6a00, State: Running, Role: LEADER
I20260812 06:17:15.297389 11028 consensus_queue.cc:237] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [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: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER }
I20260812 06:17:15.298014 11032 sys_catalog.cc:455] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 09165c51a34949d1a7f1bf703bae6a00. Latest consensus state: current_term: 1 leader_uuid: "09165c51a34949d1a7f1bf703bae6a00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER } }
I20260812 06:17:15.298184 11032 sys_catalog.cc:458] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.298164 11030 sys_catalog.cc:455] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "09165c51a34949d1a7f1bf703bae6a00" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "09165c51a34949d1a7f1bf703bae6a00" member_type: VOTER } }
I20260812 06:17:15.298338 11030 sys_catalog.cc:458] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.298810 11048 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:15.299827 11048 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:15.300084 10595 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:15.301828 11048 catalog_manager.cc:1383] Generated new cluster ID: 681e3b6496294213977a427e69c02f51
I20260812 06:17:15.301893 11048 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:15.329942 11048 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:15.330596 11048 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:15.337296 11048 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00: Generated new TSK 0
I20260812 06:17:15.337531 11048 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:15.365111 10595 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.367195 11062 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:15.367190 11063 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:15.367195 11066 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:15.367651 10595 server_base.cc:1061] running on GCE node
I20260812 06:17:15.367817 10595 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.367882 10595 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:15.367918 10595 hybrid_clock.cc:648] HybridClock initialized: now 1786515435367916 us; error 0 us; skew 500 ppm
I20260812 06:17:15.368770 10595 webserver.cc:533] Webserver started at http://127.10.88.193:39053/ using document root <none> and password file <none>
I20260812 06:17:15.368984 10595 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.369051 10595 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.369134 10595 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.369557 10595 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/instance:
uuid: "cb970b73156e46c1bd9bae02c755d229"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-ffrd"
I20260812 06:17:15.371134 10595 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:15.372174 11076 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:15.372421 10595 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:15.372512 10595 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root
uuid: "cb970b73156e46c1bd9bae02c755d229"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-ffrd"
I20260812 06:17:15.372602 10595 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-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:15.380167 10595 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.380493 10595 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.380777 10595 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:15.381292 10595 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:15.381361 10595 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.381420 10595 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:15.381454 10595 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.385798 10595 rpc_server.cc:307] RPC server started. Bound to: 127.10.88.193:32839
I20260812 06:17:15.385834 11191 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.88.193:32839 every 8 connection(s)
I20260812 06:17:15.393579 11192 heartbeater.cc:344] Connected to a master server at 127.10.88.254:44279
I20260812 06:17:15.393680 11192 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:15.393869 11192 heartbeater.cc:507] Master 127.10.88.254:44279 requested a full tablet report, sending...
I20260812 06:17:15.394495 10953 ts_manager.cc:194] Registered new tserver with Master: cb970b73156e46c1bd9bae02c755d229 (127.10.88.193:32839)
I20260812 06:17:15.395192 10595 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.00891589s
I20260812 06:17:15.395216 10953 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47636
I20260812 06:17:15.402256 10953 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47638:
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:15.411021 11130 tablet_service.cc:1511] Processing CreateTablet for tablet cba6b2fc75c6483c9dcf572423e1d78b (DEFAULT_TABLE table=heavy-update-compaction-test [id=89d350d775b34c1c9f0b45c9aa5af800]), partition=
I20260812 06:17:15.411304 11130 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet cba6b2fc75c6483c9dcf572423e1d78b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.413321 11214 tablet_bootstrap.cc:492] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Bootstrap starting.
I20260812 06:17:15.414182 11214 tablet_bootstrap.cc:654] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.415197 11214 tablet_bootstrap.cc:492] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: No bootstrap required, opened a new log
I20260812 06:17:15.415271 11214 ts_tablet_manager.cc:1403] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:15.415621 11214 raft_consensus.cc:359] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb970b73156e46c1bd9bae02c755d229" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 32839 } }
I20260812 06:17:15.415707 11214 raft_consensus.cc:385] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.415729 11214 raft_consensus.cc:740] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cb970b73156e46c1bd9bae02c755d229, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.415830 11214 consensus_queue.cc:260] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [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: "cb970b73156e46c1bd9bae02c755d229" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 32839 } }
I20260812 06:17:15.415939 11214 raft_consensus.cc:399] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.415992 11214 raft_consensus.cc:493] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.416072 11214 raft_consensus.cc:3060] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.417026 11214 raft_consensus.cc:515] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb970b73156e46c1bd9bae02c755d229" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 32839 } }
I20260812 06:17:15.417183 11214 leader_election.cc:304] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [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: cb970b73156e46c1bd9bae02c755d229; no voters: 
I20260812 06:17:15.417382 11214 leader_election.cc:290] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.417516 11219 raft_consensus.cc:2804] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.417729 11219 raft_consensus.cc:697] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 1 LEADER]: Becoming Leader. State: Replica: cb970b73156e46c1bd9bae02c755d229, State: Running, Role: LEADER
I20260812 06:17:15.417733 11214 ts_tablet_manager.cc:1434] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:15.417737 11192 heartbeater.cc:499] Master 127.10.88.254:44279 was elected leader, sending a full tablet report...
I20260812 06:17:15.417883 11219 consensus_queue.cc:237] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [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: "cb970b73156e46c1bd9bae02c755d229" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 32839 } }
I20260812 06:17:15.419188 10953 catalog_manager.cc:5719] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 reported cstate change: term changed from 0 to 1, leader changed from <none> to cb970b73156e46c1bd9bae02c755d229 (127.10.88.193). New cstate: current_term: 1 leader_uuid: "cb970b73156e46c1bd9bae02c755d229" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb970b73156e46c1bd9bae02c755d229" member_type: VOTER last_known_addr { host: "127.10.88.193" port: 32839 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:15.480159 10595 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.011s
I20260812 06:17:15.637012 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=19.054940
I20260812 06:17:15.814723 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.177s	user 0.117s	sys 0.057s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1042,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47299,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:15.817198 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b): free 20743880 bytes of WAL
I20260812 06:17:15.817458 11086 log_reader.cc:385] T cba6b2fc75c6483c9dcf572423e1d78b: removed 2 log segments from log reader
I20260812 06:17:15.817538 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000001 (ops 1-6)
I20260812 06:17:15.817649 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000002 (ops 7-11)
I20260812 06:17:15.823895 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:15.824534 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b): 16411395 bytes on disk
I20260812 06:17:15.825165 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.825757 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:15.845450 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.846035 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:16.005012 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.159s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":535,"lbm_read_time_us":12371,"lbm_reads_lt_1ms":460,"lbm_write_time_us":28803,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":334,"threads_started":5,"update_count":2000}
I20260812 06:17:16.005685 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:16.063444 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.058s	user 0.040s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26024,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.063951 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:16.075788 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4519,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.076268 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:16.264674 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.188s	user 0.124s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1089,"lbm_read_time_us":12892,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33617,"lbm_writes_lt_1ms":543,"mutex_wait_us":363,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32384,"update_count":2500}
I20260812 06:17:16.265395 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:16.332253 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.067s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25337,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.333067 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:16.345352 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4522,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.345893 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:16.524557 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.178s	user 0.123s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":801,"lbm_read_time_us":14072,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31237,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:17:16.525218 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:16.585498 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.060s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21870,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.586072 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:16.597653 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.598333 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:16.769856 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.171s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":236,"lbm_read_time_us":12409,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27979,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:17:16.770649 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:16.827276 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.056s	user 0.029s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19642,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.827831 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:16.841841 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.845331 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:17.034351 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.189s	user 0.110s	sys 0.079s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":14537,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28510,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:17:17.035418 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:17.102847 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.067s	user 0.025s	sys 0.040s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23797,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.103534 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:17.117866 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5732,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.118323 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:17.166934 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.048s	user 0.034s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1140,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1885,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:17.167569 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b): free 120553376 bytes of WAL
I20260812 06:17:17.167812 11086 log_reader.cc:385] T cba6b2fc75c6483c9dcf572423e1d78b: removed 12 log segments from log reader
I20260812 06:17:17.167855 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000003 (ops 12-16)
I20260812 06:17:17.167912 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000004 (ops 17-20)
I20260812 06:17:17.167955 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000005 (ops 21-25)
I20260812 06:17:17.168015 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000006 (ops 26-30)
I20260812 06:17:17.168053 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000007 (ops 31-35)
I20260812 06:17:17.168092 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000008 (ops 36-40)
I20260812 06:17:17.168128 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000009 (ops 41-45)
I20260812 06:17:17.168166 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000010 (ops 46-50)
I20260812 06:17:17.168203 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000011 (ops 51-55)
I20260812 06:17:17.168241 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000012 (ops 56-60)
I20260812 06:17:17.168282 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000013 (ops 61-64)
I20260812 06:17:17.168320 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000014 (ops 65-69)
I20260812 06:17:17.198011 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:17.198390 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b): 462 bytes on disk
I20260812 06:17:17.198798 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.199337 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=3.181125
I20260812 06:17:17.215708 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4603,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:17.216146 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:17.228359 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4947,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.228847 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:17.482698 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.254s	user 0.138s	sys 0.113s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":143,"lbm_read_time_us":18228,"lbm_reads_lt_1ms":774,"lbm_write_time_us":42509,"lbm_writes_lt_1ms":743,"mutex_wait_us":29,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":23936,"thread_start_us":99,"threads_started":1,"update_count":3500}
I20260812 06:17:17.485209 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=18.063937
I20260812 06:17:17.568667 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.081s	user 0.048s	sys 0.020s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":32342,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:17.569289 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:17.582173 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.582835 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:17.806401 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.223s	user 0.148s	sys 0.074s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":348,"lbm_read_time_us":17942,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37187,"lbm_writes_lt_1ms":643,"mutex_wait_us":121,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":3000}
I20260812 06:17:17.807235 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=16.079562
I20260812 06:17:17.867177 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.060s	user 0.037s	sys 0.020s Metrics: {"bytes_written":17599604,"delete_count":0,"lbm_write_time_us":27376,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2145}
I20260812 06:17:17.867939 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:17.888528 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.020s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3323184,"delete_count":0,"lbm_write_time_us":3837,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:17.889117 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:17.903054 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5634,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.903630 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:18.116253 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.212s	user 0.135s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877193,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":122,"lbm_read_time_us":16361,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36588,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":86400,"update_count":3000}
I20260812 06:17:18.117141 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=15.087375
I20260812 06:17:18.166743 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.049s	user 0.027s	sys 0.020s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":22220,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:18.167353 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:18.183620 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5785,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:18.184157 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:18.369992 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.186s	user 0.133s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774677,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":14393,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30938,"lbm_writes_lt_1ms":543,"mutex_wait_us":362,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:17:18.370680 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:18.432577 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.062s	user 0.032s	sys 0.025s Metrics: {"bytes_written":16532974,"delete_count":0,"lbm_write_time_us":22297,"lbm_writes_lt_1ms":406,"mutex_wait_us":126,"reinsert_count":0,"update_count":2015}
I20260812 06:17:18.433202 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:18.451936 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.019s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:18.452484 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:18.657472 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.205s	user 0.130s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":821,"lbm_read_time_us":14574,"lbm_reads_lt_1ms":564,"lbm_write_time_us":34171,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:18.658131 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=15.087375
I20260812 06:17:18.721334 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.063s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22347,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:18.721827 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=4.173312
I20260812 06:17:18.738802 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.017s	user 0.006s	sys 0.009s Metrics: {"bytes_written":5579533,"delete_count":0,"lbm_write_time_us":6980,"lbm_writes_lt_1ms":139,"reinsert_count":0,"update_count":680}
I20260812 06:17:18.739279 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.196750
I20260812 06:17:18.746143 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.007s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2215504,"delete_count":0,"lbm_write_time_us":2346,"lbm_writes_lt_1ms":57,"reinsert_count":0,"update_count":270}
I20260812 06:17:18.746562 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:18.782058 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.035s	user 0.031s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1306,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:18.782740 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b): free 121006455 bytes of WAL
I20260812 06:17:18.783016 11086 log_reader.cc:385] T cba6b2fc75c6483c9dcf572423e1d78b: removed 12 log segments from log reader
I20260812 06:17:18.783075 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000015 (ops 70-74)
I20260812 06:17:18.783114 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000016 (ops 75-79)
I20260812 06:17:18.783146 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000017 (ops 80-84)
I20260812 06:17:18.783177 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000018 (ops 85-88)
I20260812 06:17:18.783205 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000019 (ops 89-93)
I20260812 06:17:18.783231 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000020 (ops 94-98)
I20260812 06:17:18.783260 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000021 (ops 99-103)
I20260812 06:17:18.783295 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000022 (ops 104-108)
I20260812 06:17:18.783324 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000023 (ops 109-113)
I20260812 06:17:18.783349 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000024 (ops 114-118)
I20260812 06:17:18.783443 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000025 (ops 119-123)
I20260812 06:17:18.783560 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000026 (ops 124-128)
I20260812 06:17:18.815582 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:17:18.816044 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b): 472 bytes on disk
I20260812 06:17:18.816763 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":120,"lbm_reads_lt_1ms":4}
I20260812 06:17:18.817466 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:18.840687 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.023s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6427,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.841307 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:18.852501 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4527,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.853060 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:19.111872 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.259s	user 0.182s	sys 0.077s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082235,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":102,"lbm_read_time_us":19897,"lbm_reads_lt_1ms":875,"lbm_write_time_us":48482,"lbm_writes_lt_1ms":843,"mutex_wait_us":21,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":12800,"thread_start_us":80,"threads_started":1,"update_count":4000}
I20260812 06:17:19.115970 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=18.063937
I20260812 06:17:19.188416 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.072s	user 0.031s	sys 0.035s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31798,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.188899 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=3.181125
I20260812 06:17:19.202813 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5465,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.203305 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:19.213267 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.213922 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:19.423534 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.209s	user 0.167s	sys 0.041s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979625,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":891,"lbm_read_time_us":15353,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42920,"lbm_writes_lt_1ms":743,"mutex_wait_us":293,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":3500}
I20260812 06:17:19.424125 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=15.087375
I20260812 06:17:19.473453 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.049s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22358,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:19.474023 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:19.490271 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.016s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6175,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.490852 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:19.661638 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.171s	user 0.121s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1301,"lbm_read_time_us":11145,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29492,"lbm_writes_lt_1ms":543,"mutex_wait_us":564,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.662397 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:19.723639 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.061s	user 0.040s	sys 0.013s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25028,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:19.724165 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:19.735165 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4260,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.735620 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:19.942178 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.206s	user 0.143s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":727,"lbm_read_time_us":13822,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34452,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2500}
I20260812 06:17:19.942957 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:20.009915 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.067s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26279,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.010406 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:20.022518 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.023319 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:20.205451 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.182s	user 0.126s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":213,"lbm_read_time_us":12036,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33196,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23808,"update_count":2500}
I20260812 06:17:20.206027 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=14.095187
I20260812 06:17:20.268870 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.063s	user 0.040s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:20.269578 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:20.285444 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.016s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.285913 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:20.328584 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushMRSOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.042s	user 0.021s	sys 0.008s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2389,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:20.329424 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b): 473 bytes on disk
I20260812 06:17:20.329929 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: UndoDeltaBlockGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.330410 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=3.181125
I20260812 06:17:20.343683 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.013s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4794,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:20.344259 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b): free 120100583 bytes of WAL
I20260812 06:17:20.344476 11086 log_reader.cc:385] T cba6b2fc75c6483c9dcf572423e1d78b: removed 12 log segments from log reader
I20260812 06:17:20.344519 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000027 (ops 129-132)
I20260812 06:17:20.344578 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000028 (ops 133-137)
I20260812 06:17:20.344621 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000029 (ops 138-142)
I20260812 06:17:20.344650 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000030 (ops 143-146)
I20260812 06:17:20.344686 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000031 (ops 147-151)
I20260812 06:17:20.344725 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000032 (ops 152-156)
I20260812 06:17:20.344763 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000033 (ops 157-161)
I20260812 06:17:20.344801 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000034 (ops 162-166)
I20260812 06:17:20.344838 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000035 (ops 167-171)
I20260812 06:17:20.344877 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000036 (ops 172-176)
I20260812 06:17:20.344914 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000037 (ops 177-180)
I20260812 06:17:20.345034 11086 log.cc:1079] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: Deleting log segment in path: /tmp/dist-test-taskBlBJ1g/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515429590259-10595-0/minicluster-data/ts-0-root/wals/cba6b2fc75c6483c9dcf572423e1d78b/wal-000000038 (ops 181-185)
I20260812 06:17:20.371547 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: LogGCOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.027s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:17:20.371968 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:20.391276 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6831,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.391839 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=2.188937
I20260812 06:17:20.402302 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4093,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:20.402930 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:20.644999 10595 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.165s	user 1.931s	sys 0.154s
I20260812 06:17:20.653877 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.251s	user 0.182s	sys 0.067s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082269,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":21865,"lbm_reads_lt_1ms":871,"lbm_write_time_us":43283,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":4000}
I20260812 06:17:20.654397 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=18.063937
I20260812 06:17:20.696208 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: FlushDeltaMemStoresOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.042s	user 0.025s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":20655,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:20.696669 11196 maintenance_manager.cc:419] P cb970b73156e46c1bd9bae02c755d229: Scheduling MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b): perf score=1.000000
I20260812 06:17:20.729295 10595 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.003s	sys 0.000s
I20260812 06:17:20.729954 10595 tablet_server.cc:179] TabletServer@127.10.88.193:0 shutting down...
I20260812 06:17:20.833117 11086 maintenance_manager.cc:643] P cb970b73156e46c1bd9bae02c755d229: MajorDeltaCompactionOp(cba6b2fc75c6483c9dcf572423e1d78b) complete. Timing: real 0.136s	user 0.110s	sys 0.024s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":3115,"lbm_read_time_us":10607,"lbm_reads_lt_1ms":567,"lbm_write_time_us":30303,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":2420,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:17:20.833956 10595 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:20.834372 10595 tablet_replica.cc:333] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229: stopping tablet replica
I20260812 06:17:20.834573 10595 raft_consensus.cc:2243] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.834791 10595 raft_consensus.cc:2272] T cba6b2fc75c6483c9dcf572423e1d78b P cb970b73156e46c1bd9bae02c755d229 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.848634 10595 tablet_server.cc:196] TabletServer@127.10.88.193:0 shutdown complete.
I20260812 06:17:20.887995 10595 master.cc:562] Master@127.10.88.254:44279 shutting down...
I20260812 06:17:20.891871 10595 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:20.892050 10595 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:20.892103 10595 tablet_replica.cc:333] T 00000000000000000000000000000000 P 09165c51a34949d1a7f1bf703bae6a00: stopping tablet replica
I20260812 06:17:20.904613 10595 master.cc:584] Master@127.10.88.254:44279 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5756 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11400 ms total)

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