[==========] 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:04.596364 25165 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.147.126:35633
I20260812 06:17:04.597292 25165 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:04.597846 25165 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.603569 25175 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:04.603634 25165 server_base.cc:1061] running on GCE node
W20260812 06:17:04.603564 25178 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:04.603933 25174 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:04.604365 25165 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.604451 25165 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:04.604489 25165 hybrid_clock.cc:648] HybridClock initialized: now 1786515424604487 us; error 0 us; skew 500 ppm
I20260812 06:17:04.606081 25165 webserver.cc:533] Webserver started at http://127.24.147.126:46171/ using document root <none> and password file <none>
I20260812 06:17:04.606556 25165 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.606613 25165 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.606853 25165 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.608323 25165 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/master-0-root/instance:
uuid: "9a8ff3da441e4376a90b2cfc628b9939"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-q9h9"
I20260812 06:17:04.611480 25165 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:04.613338 25187 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:04.614336 25165 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:04.614428 25165 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/master-0-root
uuid: "9a8ff3da441e4376a90b2cfc628b9939"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-q9h9"
I20260812 06:17:04.614509 25165 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-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:04.635879 25165 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.636385 25165 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:04.636521 25165 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.643388 25165 rpc_server.cc:307] RPC server started. Bound to: 127.24.147.126:35633
I20260812 06:17:04.643399 25278 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.147.126:35633 every 8 connection(s)
I20260812 06:17:04.645490 25280 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:04.650676 25280 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: Bootstrap starting.
I20260812 06:17:04.652907 25280 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.653718 25280 log.cc:826] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:04.655270 25280 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: No bootstrap required, opened a new log
I20260812 06:17:04.657837 25280 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER }
I20260812 06:17:04.657994 25280 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.658088 25280 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9a8ff3da441e4376a90b2cfc628b9939, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.658586 25280 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [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: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER }
I20260812 06:17:04.658718 25280 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.658767 25280 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.658856 25280 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.659557 25280 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER }
I20260812 06:17:04.659924 25280 leader_election.cc:304] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [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: 9a8ff3da441e4376a90b2cfc628b9939; no voters: 
I20260812 06:17:04.660213 25280 leader_election.cc:290] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.660305 25283 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.660492 25283 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 1 LEADER]: Becoming Leader. State: Replica: 9a8ff3da441e4376a90b2cfc628b9939, State: Running, Role: LEADER
I20260812 06:17:04.660861 25283 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [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: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER }
I20260812 06:17:04.661154 25280 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:04.662544 25286 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9a8ff3da441e4376a90b2cfc628b9939. Latest consensus state: current_term: 1 leader_uuid: "9a8ff3da441e4376a90b2cfc628b9939" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER } }
I20260812 06:17:04.662664 25286 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.662892 25284 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9a8ff3da441e4376a90b2cfc628b9939" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9a8ff3da441e4376a90b2cfc628b9939" member_type: VOTER } }
I20260812 06:17:04.663020 25284 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:04.663043 25304 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:04.663614 25165 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:04.665292 25304 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:04.669508 25304 catalog_manager.cc:1383] Generated new cluster ID: 929c9de5d5f34ac5870dca39829a60b3
I20260812 06:17:04.669566 25304 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:04.677522 25304 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:04.678244 25304 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:04.686585 25304 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: Generated new TSK 0
I20260812 06:17:04.687031 25304 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:04.696034 25165 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:04.698261 25326 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:04.698326 25325 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:04.698465 25165 server_base.cc:1061] running on GCE node
W20260812 06:17:04.698556 25330 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:04.698760 25165 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:04.698801 25165 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:04.698822 25165 hybrid_clock.cc:648] HybridClock initialized: now 1786515424698821 us; error 0 us; skew 500 ppm
I20260812 06:17:04.699592 25165 webserver.cc:533] Webserver started at http://127.24.147.65:42955/ using document root <none> and password file <none>
I20260812 06:17:04.699738 25165 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:04.699786 25165 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:04.699857 25165 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:04.700160 25165 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/instance:
uuid: "7d9db29f354447a6839cd0539dc7e8c2"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-q9h9"
I20260812 06:17:04.701498 25165 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.702422 25337 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:04.702675 25165 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:04.702736 25165 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root
uuid: "7d9db29f354447a6839cd0539dc7e8c2"
format_stamp: "Formatted at 2026-08-12 06:17:04 on dist-test-slave-q9h9"
I20260812 06:17:04.702800 25165 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-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:04.714138 25165 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:04.714663 25165 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:04.715057 25165 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:04.715762 25165 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:04.715808 25165 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.715848 25165 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:04.715876 25165 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:04.721619 25165 rpc_server.cc:307] RPC server started. Bound to: 127.24.147.65:39395
I20260812 06:17:04.721662 25444 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.147.65:39395 every 8 connection(s)
I20260812 06:17:04.733579 25446 heartbeater.cc:344] Connected to a master server at 127.24.147.126:35633
I20260812 06:17:04.733809 25446 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:04.734298 25446 heartbeater.cc:507] Master 127.24.147.126:35633 requested a full tablet report, sending...
I20260812 06:17:04.735707 25221 ts_manager.cc:194] Registered new tserver with Master: 7d9db29f354447a6839cd0539dc7e8c2 (127.24.147.65:39395)
I20260812 06:17:04.735836 25165 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013642671s
I20260812 06:17:04.737147 25221 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55822
I20260812 06:17:04.744076 25221 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55832:
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:04.757517 25383 tablet_service.cc:1511] Processing CreateTablet for tablet 18f2f87b1cf74e99859ff3d37139a1db (DEFAULT_TABLE table=heavy-update-compaction-test [id=5de16c875e4d46c78f311ea0ea6813a5]), partition=
I20260812 06:17:04.758064 25383 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 18f2f87b1cf74e99859ff3d37139a1db. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:04.760810 25474 tablet_bootstrap.cc:492] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Bootstrap starting.
I20260812 06:17:04.761649 25474 tablet_bootstrap.cc:654] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:04.762640 25474 tablet_bootstrap.cc:492] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: No bootstrap required, opened a new log
I20260812 06:17:04.762741 25474 ts_tablet_manager.cc:1403] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:04.763140 25474 raft_consensus.cc:359] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7d9db29f354447a6839cd0539dc7e8c2" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 39395 } }
I20260812 06:17:04.763227 25474 raft_consensus.cc:385] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:04.763252 25474 raft_consensus.cc:740] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7d9db29f354447a6839cd0539dc7e8c2, State: Initialized, Role: FOLLOWER
I20260812 06:17:04.763389 25474 consensus_queue.cc:260] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [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: "7d9db29f354447a6839cd0539dc7e8c2" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 39395 } }
I20260812 06:17:04.763468 25474 raft_consensus.cc:399] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:04.763502 25474 raft_consensus.cc:493] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:04.763549 25474 raft_consensus.cc:3060] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:04.764441 25474 raft_consensus.cc:515] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7d9db29f354447a6839cd0539dc7e8c2" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 39395 } }
I20260812 06:17:04.764559 25474 leader_election.cc:304] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [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: 7d9db29f354447a6839cd0539dc7e8c2; no voters: 
I20260812 06:17:04.764729 25474 leader_election.cc:290] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:04.765000 25477 raft_consensus.cc:2804] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:04.765054 25474 ts_tablet_manager.cc:1434] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:04.765230 25477 raft_consensus.cc:697] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 1 LEADER]: Becoming Leader. State: Replica: 7d9db29f354447a6839cd0539dc7e8c2, State: Running, Role: LEADER
I20260812 06:17:04.765323 25446 heartbeater.cc:499] Master 127.24.147.126:35633 was elected leader, sending a full tablet report...
I20260812 06:17:04.765405 25477 consensus_queue.cc:237] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [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: "7d9db29f354447a6839cd0539dc7e8c2" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 39395 } }
I20260812 06:17:04.767763 25221 catalog_manager.cc:5719] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7d9db29f354447a6839cd0539dc7e8c2 (127.24.147.65). New cstate: current_term: 1 leader_uuid: "7d9db29f354447a6839cd0539dc7e8c2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7d9db29f354447a6839cd0539dc7e8c2" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 39395 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:04.832432 25165 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.012s	sys 0.012s
I20260812 06:17:04.972680 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=19.054940
I20260812 06:17:05.120620 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.148s	user 0.099s	sys 0.043s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":204,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":727,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36584,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":122,"threads_started":1,"update_count":1450}
I20260812 06:17:05.121532 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling LogGCOp(18f2f87b1cf74e99859ff3d37139a1db): free 20743880 bytes of WAL
I20260812 06:17:05.121793 25347 log_reader.cc:385] T 18f2f87b1cf74e99859ff3d37139a1db: removed 2 log segments from log reader
I20260812 06:17:05.121850 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000001 (ops 1-6)
I20260812 06:17:05.121942 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000002 (ops 7-11)
I20260812 06:17:05.125486 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: LogGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:05.125765 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:05.138685 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.139235 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:05.275765 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.136s	user 0.106s	sys 0.027s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303031,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":450,"lbm_read_time_us":7795,"lbm_reads_lt_1ms":454,"lbm_write_time_us":26058,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":291,"threads_started":5,"update_count":1950}
I20260812 06:17:05.276394 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:05.311705 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.035s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15325,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.312268 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:05.323166 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.323633 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db): 16821650 bytes on disk
I20260812 06:17:05.324237 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.324692 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:05.443058 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.118s	user 0.084s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":8220,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23296,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:05.443547 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:05.480146 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.036s	user 0.017s	sys 0.010s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12600,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.480611 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:05.490134 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.490528 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:05.608240 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.118s	user 0.104s	sys 0.013s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":903,"lbm_read_time_us":8006,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23196,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:05.608686 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:05.658237 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.049s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15155,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.658731 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:05.668690 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3864,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.669127 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:05.802033 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.133s	user 0.081s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":113,"lbm_read_time_us":10277,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22653,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:05.802507 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:05.844975 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.041s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15075,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.845492 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:05.855284 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.855684 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:05.980168 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.124s	user 0.096s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":9182,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25107,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:05.980801 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:06.020884 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.040s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15439,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.021373 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.031272 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.031817 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:06.153364 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.121s	user 0.109s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":217,"lbm_read_time_us":9656,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22474,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:17:06.153990 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:06.193153 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.039s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13631,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.193739 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.208909 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5401,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.209369 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:06.326947 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.117s	user 0.086s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":8435,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23880,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":2000}
I20260812 06:17:06.327471 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:06.370811 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.043s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13306,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.371313 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.381279 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.381705 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:06.417246 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.035s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1039,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1339,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:06.418193 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling LogGCOp(18f2f87b1cf74e99859ff3d37139a1db): free 124710243 bytes of WAL
I20260812 06:17:06.418434 25347 log_reader.cc:385] T 18f2f87b1cf74e99859ff3d37139a1db: removed 12 log segments from log reader
I20260812 06:17:06.418485 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000003 (ops 12-16)
I20260812 06:17:06.418524 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000004 (ops 17-21)
I20260812 06:17:06.418553 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000005 (ops 22-26)
I20260812 06:17:06.418586 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000006 (ops 27-31)
I20260812 06:17:06.418614 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000007 (ops 32-36)
I20260812 06:17:06.418645 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000008 (ops 37-41)
I20260812 06:17:06.418684 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000009 (ops 42-46)
I20260812 06:17:06.418716 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000010 (ops 47-51)
I20260812 06:17:06.418745 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000011 (ops 52-56)
I20260812 06:17:06.418776 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000012 (ops 57-61)
I20260812 06:17:06.418807 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000013 (ops 62-66)
I20260812 06:17:06.418838 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000014 (ops 67-71)
I20260812 06:17:06.441474 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: LogGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:17:06.441998 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db): 482 bytes on disk
I20260812 06:17:06.442545 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.443110 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.458843 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.016s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.459235 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.469260 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3684,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.469630 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:06.653292 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.184s	user 0.123s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918332,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":219,"lbm_read_time_us":13607,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30121,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18176,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:17:06.653729 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=14.095187
I20260812 06:17:06.706156 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.052s	user 0.037s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21746,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.706560 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:06.843187 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.136s	user 0.096s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":847,"lbm_read_time_us":9681,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21890,"lbm_writes_lt_1ms":443,"mutex_wait_us":320,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":30080,"update_count":2000}
I20260812 06:17:06.843868 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:06.879194 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15204,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.879637 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:06.891676 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4707,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.892083 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.016348 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.124s	user 0.090s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":8252,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23045,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:17:07.017009 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:07.058342 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.041s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.058830 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:07.068910 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.069514 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.194209 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.124s	user 0.100s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":10008,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22775,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:17:07.194727 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:07.236137 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.041s	user 0.032s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17386,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.236629 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:07.247298 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3946,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.247877 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.361548 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.112s	user 0.091s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":238,"lbm_read_time_us":10102,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20320,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:07.362149 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:07.406678 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.044s	user 0.019s	sys 0.024s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16300,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.407147 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:07.417026 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3776,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.417505 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.558713 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.141s	user 0.125s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":255,"lbm_read_time_us":11007,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23180,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.559204 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:07.600521 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.041s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15415,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.600977 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:07.610881 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.611507 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.728785 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.117s	user 0.101s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":9355,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21631,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":2000}
I20260812 06:17:07.729310 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:07.768743 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.039s	user 0.018s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15848,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.769228 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:07.779258 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3896,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.779978 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:07.809438 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":166,"dirs.run_wall_time_us":998,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1866,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:07.810222 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling LogGCOp(18f2f87b1cf74e99859ff3d37139a1db): free 133024393 bytes of WAL
I20260812 06:17:07.810454 25347 log_reader.cc:385] T 18f2f87b1cf74e99859ff3d37139a1db: removed 13 log segments from log reader
I20260812 06:17:07.810524 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000015 (ops 72-76)
I20260812 06:17:07.810568 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000016 (ops 77-81)
I20260812 06:17:07.810603 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000017 (ops 82-86)
I20260812 06:17:07.810632 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000018 (ops 87-91)
I20260812 06:17:07.810660 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000019 (ops 92-96)
I20260812 06:17:07.810688 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000020 (ops 97-101)
I20260812 06:17:07.810726 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000021 (ops 102-106)
I20260812 06:17:07.810761 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000022 (ops 107-111)
I20260812 06:17:07.810788 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000023 (ops 112-116)
I20260812 06:17:07.810817 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000024 (ops 117-121)
I20260812 06:17:07.810845 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000025 (ops 122-126)
I20260812 06:17:07.810876 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000026 (ops 127-130)
I20260812 06:17:07.810907 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000027 (ops 131-135)
I20260812 06:17:07.839289 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: LogGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.029s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:17:07.839743 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=4.173312
I20260812 06:17:07.853730 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":5825681,"delete_count":0,"lbm_write_time_us":5627,"lbm_writes_lt_1ms":145,"reinsert_count":0,"update_count":710}
I20260812 06:17:07.854251 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db): 472 bytes on disk
I20260812 06:17:07.854674 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.855216 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.196750
I20260812 06:17:07.864569 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2379604,"delete_count":0,"lbm_write_time_us":2925,"lbm_writes_lt_1ms":61,"reinsert_count":0,"update_count":290}
I20260812 06:17:07.865103 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:08.035113 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.170s	user 0.137s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918296,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":524,"lbm_read_time_us":12496,"lbm_reads_lt_1ms":666,"lbm_write_time_us":35185,"lbm_writes_lt_1ms":643,"mutex_wait_us":324,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:17:08.035645 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=14.095187
I20260812 06:17:08.123234 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.087s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":64544,"lbm_writes_1-10_ms":1,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.123708 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:08.145432 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.022s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4184707,"delete_count":0,"lbm_write_time_us":4979,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:17:08.145824 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:08.155169 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3577,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:08.155540 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:08.324677 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.169s	user 0.138s	sys 0.023s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1023,"lbm_read_time_us":12756,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32546,"lbm_writes_lt_1ms":643,"mutex_wait_us":325,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:08.325145 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=14.095187
I20260812 06:17:08.376276 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.051s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21119,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.376952 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:08.393631 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.394173 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:08.567579 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.173s	user 0.121s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":113,"lbm_read_time_us":11289,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27160,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:17:08.568089 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=14.095187
I20260812 06:17:08.606797 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.039s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16538,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.607314 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:08.617044 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.617453 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:08.748170 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.131s	user 0.097s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":9286,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26436,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:17:08.748878 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=11.118625
I20260812 06:17:08.777436 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.028s	user 0.014s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12455,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:08.777899 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:08.789305 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4373,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:08.789767 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:08.926877 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.137s	user 0.112s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":8644,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25343,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:08.927371 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:08.961055 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.033s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15166,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:08.961550 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:09.064347 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.103s	user 0.081s	sys 0.019s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":874,"lbm_read_time_us":6795,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18958,"lbm_writes_lt_1ms":343,"mutex_wait_us":308,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.064966 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:09.102854 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.038s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13228,"lbm_writes_lt_1ms":303,"mutex_wait_us":3,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.103294 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:09.113332 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3820,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.113850 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:09.141675 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushMRSOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":150,"dirs.run_wall_time_us":1013,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1628,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:09.142462 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling LogGCOp(18f2f87b1cf74e99859ff3d37139a1db): free 120553650 bytes of WAL
I20260812 06:17:09.142695 25347 log_reader.cc:385] T 18f2f87b1cf74e99859ff3d37139a1db: removed 12 log segments from log reader
I20260812 06:17:09.142765 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000028 (ops 136-140)
I20260812 06:17:09.142850 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000029 (ops 141-145)
I20260812 06:17:09.142889 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000030 (ops 146-150)
I20260812 06:17:09.142916 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000031 (ops 151-154)
I20260812 06:17:09.142946 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000032 (ops 155-159)
I20260812 06:17:09.142975 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000033 (ops 160-164)
I20260812 06:17:09.143004 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000034 (ops 165-169)
I20260812 06:17:09.143034 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000035 (ops 170-174)
I20260812 06:17:09.143066 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000036 (ops 175-179)
I20260812 06:17:09.143095 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000037 (ops 180-184)
I20260812 06:17:09.143121 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000038 (ops 185-188)
I20260812 06:17:09.143149 25347 log.cc:1079] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/18f2f87b1cf74e99859ff3d37139a1db/wal-000000039 (ops 189-193)
I20260812 06:17:09.169507 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: LogGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:09.169900 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=3.181125
I20260812 06:17:09.185992 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.016s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4759050,"delete_count":0,"lbm_write_time_us":5013,"lbm_writes_lt_1ms":119,"reinsert_count":0,"update_count":580}
I20260812 06:17:09.186391 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=2.188937
I20260812 06:17:09.194746 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.008s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":3132,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:17:09.195099 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db): 462 bytes on disk
I20260812 06:17:09.195441 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: UndoDeltaBlockGCOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.195896 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:09.325616 25165 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.493s	user 1.629s	sys 0.110s
I20260812 06:17:09.382748 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.187s	user 0.132s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14037,"lbm_reads_lt_1ms":670,"lbm_write_time_us":30879,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:17:09.383195 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=10.126437
I20260812 06:17:09.409943 25165 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.001s	sys 0.000s
I20260812 06:17:09.410609 25165 tablet_server.cc:179] TabletServer@127.24.147.65:0 shutting down...
I20260812 06:17:09.414638 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: FlushDeltaMemStoresOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.031s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13427,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.415122 25447 maintenance_manager.cc:419] P 7d9db29f354447a6839cd0539dc7e8c2: Scheduling MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db): perf score=1.000000
I20260812 06:17:09.503418 25347 maintenance_manager.cc:643] P 7d9db29f354447a6839cd0539dc7e8c2: MajorDeltaCompactionOp(18f2f87b1cf74e99859ff3d37139a1db) complete. Timing: real 0.088s	user 0.067s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":842,"lbm_read_time_us":6060,"lbm_reads_lt_1ms":367,"lbm_write_time_us":15601,"lbm_writes_lt_1ms":343,"mutex_wait_us":85,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.503961 25165 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:09.504401 25165 tablet_replica.cc:333] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2: stopping tablet replica
I20260812 06:17:09.504649 25165 raft_consensus.cc:2243] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.504875 25165 raft_consensus.cc:2272] T 18f2f87b1cf74e99859ff3d37139a1db P 7d9db29f354447a6839cd0539dc7e8c2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.510424 25165 tablet_server.cc:196] TabletServer@127.24.147.65:0 shutdown complete.
I20260812 06:17:09.534135 25165 master.cc:562] Master@127.24.147.126:35633 shutting down...
I20260812 06:17:09.537664 25165 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:09.537809 25165 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:09.537880 25165 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9a8ff3da441e4376a90b2cfc628b9939: stopping tablet replica
I20260812 06:17:09.549737 25165 master.cc:584] Master@127.24.147.126:35633 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5027 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:09.623420 25165 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.24.147.126:43217
I20260812 06:17:09.623770 25165 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.625583 25505 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:09.625721 25504 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.625815 25507 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:09.625974 25165 server_base.cc:1061] running on GCE node
I20260812 06:17:09.626160 25165 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.626212 25165 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.626236 25165 hybrid_clock.cc:648] HybridClock initialized: now 1786515429626236 us; error 0 us; skew 500 ppm
I20260812 06:17:09.627041 25165 webserver.cc:533] Webserver started at http://127.24.147.126:40207/ using document root <none> and password file <none>
I20260812 06:17:09.627193 25165 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.627239 25165 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.627311 25165 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.627656 25165 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/master-0-root/instance:
uuid: "48c19bf78f45490ea166a3dad354814c"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-q9h9"
I20260812 06:17:09.629122 25165 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:09.630427 25519 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.630703 25165 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:09.630782 25165 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/master-0-root
uuid: "48c19bf78f45490ea166a3dad354814c"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-q9h9"
I20260812 06:17:09.630849 25165 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-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.643813 25165 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.644071 25165 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.647861 25165 rpc_server.cc:307] RPC server started. Bound to: 127.24.147.126:43217
I20260812 06:17:09.664047 25608 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.147.126:43217 every 8 connection(s)
I20260812 06:17:09.664419 25610 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.666399 25610 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c: Bootstrap starting.
I20260812 06:17:09.667098 25610 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.667966 25610 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c: No bootstrap required, opened a new log
I20260812 06:17:09.668300 25610 raft_consensus.cc:359] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER }
I20260812 06:17:09.668375 25610 raft_consensus.cc:385] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.668395 25610 raft_consensus.cc:740] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 48c19bf78f45490ea166a3dad354814c, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.668497 25610 consensus_queue.cc:260] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [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: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER }
I20260812 06:17:09.668551 25610 raft_consensus.cc:399] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.668571 25610 raft_consensus.cc:493] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.668602 25610 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.669174 25610 raft_consensus.cc:515] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER }
I20260812 06:17:09.669281 25610 leader_election.cc:304] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [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: 48c19bf78f45490ea166a3dad354814c; no voters: 
I20260812 06:17:09.669413 25610 leader_election.cc:290] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.669530 25623 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.669723 25623 raft_consensus.cc:697] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 1 LEADER]: Becoming Leader. State: Replica: 48c19bf78f45490ea166a3dad354814c, State: Running, Role: LEADER
I20260812 06:17:09.669812 25610 sys_catalog.cc:565] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:09.669870 25623 consensus_queue.cc:237] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [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: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER }
I20260812 06:17:09.670305 25626 sys_catalog.cc:455] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "48c19bf78f45490ea166a3dad354814c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER } }
I20260812 06:17:09.670329 25627 sys_catalog.cc:455] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 48c19bf78f45490ea166a3dad354814c. Latest consensus state: current_term: 1 leader_uuid: "48c19bf78f45490ea166a3dad354814c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "48c19bf78f45490ea166a3dad354814c" member_type: VOTER } }
I20260812 06:17:09.670400 25626 sys_catalog.cc:458] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.670413 25627 sys_catalog.cc:458] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:09.670671 25633 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:09.671452 25633 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:09.671655 25165 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:09.673180 25633 catalog_manager.cc:1383] Generated new cluster ID: 751212a83685422ca5d5b7ea85f4fd03
I20260812 06:17:09.673233 25633 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:09.685113 25633 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:09.685582 25633 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:09.690593 25633 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c: Generated new TSK 0
I20260812 06:17:09.690721 25633 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:09.703672 25165 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:09.705209 25650 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.705343 25165 server_base.cc:1061] running on GCE node
W20260812 06:17:09.705292 25659 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.705420 25654 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.705600 25165 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:09.705641 25165 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.705654 25165 hybrid_clock.cc:648] HybridClock initialized: now 1786515429705654 us; error 0 us; skew 500 ppm
I20260812 06:17:09.706377 25165 webserver.cc:533] Webserver started at http://127.24.147.65:44809/ using document root <none> and password file <none>
I20260812 06:17:09.706493 25165 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:09.706538 25165 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:09.706593 25165 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:09.706884 25165 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/instance:
uuid: "e953fb6b2ffa479f9cb76a73e9552b9d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-q9h9"
I20260812 06:17:09.708137 25165 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:09.708925 25665 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.709142 25165 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:09.709205 25165 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root
uuid: "e953fb6b2ffa479f9cb76a73e9552b9d"
format_stamp: "Formatted at 2026-08-12 06:17:09 on dist-test-slave-q9h9"
I20260812 06:17:09.709268 25165 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-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.724229 25165 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:09.724488 25165 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:09.724730 25165 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:09.725126 25165 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:09.725160 25165 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.725199 25165 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:09.725226 25165 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:09.728950 25165 rpc_server.cc:307] RPC server started. Bound to: 127.24.147.65:35561
I20260812 06:17:09.728976 25768 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.24.147.65:35561 every 8 connection(s)
I20260812 06:17:09.739563 25770 heartbeater.cc:344] Connected to a master server at 127.24.147.126:43217
I20260812 06:17:09.739655 25770 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:09.739840 25770 heartbeater.cc:507] Master 127.24.147.126:43217 requested a full tablet report, sending...
I20260812 06:17:09.740463 25547 ts_manager.cc:194] Registered new tserver with Master: e953fb6b2ffa479f9cb76a73e9552b9d (127.24.147.65:35561)
I20260812 06:17:09.741125 25547 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:55680
I20260812 06:17:09.741302 25165 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011987029s
I20260812 06:17:09.747468 25547 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:55688:
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.755304 25712 tablet_service.cc:1511] Processing CreateTablet for tablet c1d704948173470396e64c62438f78c9 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2cabfe54ac6946eeb080fcb2f3e3875f]), partition=
I20260812 06:17:09.755538 25712 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c1d704948173470396e64c62438f78c9. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:09.757328 25791 tablet_bootstrap.cc:492] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Bootstrap starting.
I20260812 06:17:09.758281 25791 tablet_bootstrap.cc:654] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:09.759370 25791 tablet_bootstrap.cc:492] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: No bootstrap required, opened a new log
I20260812 06:17:09.759461 25791 ts_tablet_manager.cc:1403] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:09.759878 25791 raft_consensus.cc:359] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e953fb6b2ffa479f9cb76a73e9552b9d" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 35561 } }
I20260812 06:17:09.759964 25791 raft_consensus.cc:385] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:09.759986 25791 raft_consensus.cc:740] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e953fb6b2ffa479f9cb76a73e9552b9d, State: Initialized, Role: FOLLOWER
I20260812 06:17:09.760106 25791 consensus_queue.cc:260] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [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: "e953fb6b2ffa479f9cb76a73e9552b9d" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 35561 } }
I20260812 06:17:09.760182 25791 raft_consensus.cc:399] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:09.760216 25791 raft_consensus.cc:493] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:09.760274 25791 raft_consensus.cc:3060] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:09.761029 25791 raft_consensus.cc:515] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e953fb6b2ffa479f9cb76a73e9552b9d" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 35561 } }
I20260812 06:17:09.761154 25791 leader_election.cc:304] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [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: e953fb6b2ffa479f9cb76a73e9552b9d; no voters: 
I20260812 06:17:09.761351 25791 leader_election.cc:290] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:09.761458 25798 raft_consensus.cc:2804] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:09.761649 25791 ts_tablet_manager.cc:1434] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:09.761711 25798 raft_consensus.cc:697] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 1 LEADER]: Becoming Leader. State: Replica: e953fb6b2ffa479f9cb76a73e9552b9d, State: Running, Role: LEADER
I20260812 06:17:09.761710 25770 heartbeater.cc:499] Master 127.24.147.126:43217 was elected leader, sending a full tablet report...
I20260812 06:17:09.761891 25798 consensus_queue.cc:237] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [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: "e953fb6b2ffa479f9cb76a73e9552b9d" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 35561 } }
I20260812 06:17:09.763139 25547 catalog_manager.cc:5719] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d reported cstate change: term changed from 0 to 1, leader changed from <none> to e953fb6b2ffa479f9cb76a73e9552b9d (127.24.147.65). New cstate: current_term: 1 leader_uuid: "e953fb6b2ffa479f9cb76a73e9552b9d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e953fb6b2ffa479f9cb76a73e9552b9d" member_type: VOTER last_known_addr { host: "127.24.147.65" port: 35561 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:09.819656 25165 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.016s	sys 0.008s
I20260812 06:17:09.979745 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushMRSOp(c1d704948173470396e64c62438f78c9): perf score=23.023690
I20260812 06:17:10.132190 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushMRSOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.152s	user 0.090s	sys 0.060s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":799,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39435,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:17:10.132858 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling LogGCOp(c1d704948173470396e64c62438f78c9): free 20743880 bytes of WAL
I20260812 06:17:10.133101 25670 log_reader.cc:385] T c1d704948173470396e64c62438f78c9: removed 2 log segments from log reader
I20260812 06:17:10.133147 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000001 (ops 1-6)
I20260812 06:17:10.133198 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000002 (ops 7-11)
I20260812 06:17:10.136986 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: LogGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:10.137310 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9): 20513814 bytes on disk
I20260812 06:17:10.137697 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.138088 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:10.157727 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.020s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.158138 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:10.167613 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3606,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.167981 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:10.322413 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.154s	user 0.127s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815801,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1183,"lbm_read_time_us":11888,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28214,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"thread_start_us":268,"threads_started":5,"update_count":2500}
I20260812 06:17:10.322815 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:10.372327 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.049s	user 0.029s	sys 0.018s Metrics: {"bytes_written":16409937,"delete_count":0,"lbm_write_time_us":20505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.372844 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:10.384766 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.012s	user 0.000s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.385213 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:10.535578 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.150s	user 0.119s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815718,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":607,"lbm_read_time_us":9613,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27790,"lbm_writes_lt_1ms":543,"mutex_wait_us":320,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:17:10.536084 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:10.583249 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.047s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20872,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.583796 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:10.736831 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.153s	user 0.085s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":624,"lbm_read_time_us":11537,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21915,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:17:10.737355 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:10.778702 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.041s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17730,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.779145 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:10.788770 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3757,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.789369 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:10.982602 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.193s	user 0.128s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":269,"lbm_read_time_us":13086,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31068,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:17:10.983059 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:11.036105 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.053s	user 0.034s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20947,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.036579 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:11.046618 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3845,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.047122 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:11.205806 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.158s	user 0.095s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":10429,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29452,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66816,"update_count":2500}
I20260812 06:17:11.206293 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:11.254097 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.048s	user 0.029s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.254566 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:11.264469 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3691,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.265009 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushMRSOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:11.296105 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushMRSOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1229,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1699,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:11.296672 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling LogGCOp(c1d704948173470396e64c62438f78c9): free 120100317 bytes of WAL
I20260812 06:17:11.296886 25670 log_reader.cc:385] T c1d704948173470396e64c62438f78c9: removed 12 log segments from log reader
I20260812 06:17:11.296931 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000003 (ops 12-16)
I20260812 06:17:11.296957 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000004 (ops 17-20)
I20260812 06:17:11.296986 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000005 (ops 21-25)
I20260812 06:17:11.297017 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000006 (ops 26-30)
I20260812 06:17:11.297050 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000007 (ops 31-35)
I20260812 06:17:11.297082 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000008 (ops 36-40)
I20260812 06:17:11.297113 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000009 (ops 41-45)
I20260812 06:17:11.297145 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000010 (ops 46-50)
I20260812 06:17:11.297176 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000011 (ops 51-54)
I20260812 06:17:11.297207 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000012 (ops 55-59)
I20260812 06:17:11.297231 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000013 (ops 60-64)
I20260812 06:17:11.297271 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000014 (ops 65-68)
I20260812 06:17:11.318722 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: LogGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:11.319092 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9): 462 bytes on disk
I20260812 06:17:11.319561 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.320008 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=3.181125
I20260812 06:17:11.341820 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.022s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4056,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:11.342219 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:11.351207 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3314,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.351543 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:11.608604 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.257s	user 0.161s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020736,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":212,"lbm_read_time_us":16405,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39737,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:17:11.609071 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=18.063937
I20260812 06:17:11.658994 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.050s	user 0.038s	sys 0.011s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":22383,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:11.659480 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:11.827430 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.168s	user 0.131s	sys 0.036s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815568,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":458,"lbm_read_time_us":12881,"lbm_reads_lt_1ms":563,"lbm_write_time_us":26546,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:17:11.827950 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:11.877390 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.049s	user 0.019s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17306,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.877892 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:11.888399 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.888861 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:12.073499 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.184s	user 0.140s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":334,"lbm_read_time_us":12145,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30278,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.073952 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:12.132040 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.058s	user 0.020s	sys 0.036s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23241,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.132539 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:12.148241 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6116,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.148753 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:12.311400 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.162s	user 0.099s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":11378,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26063,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:12.311890 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:12.362555 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.051s	user 0.034s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21100,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:17:12.363035 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:12.373232 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3770,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.373800 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:12.556417 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.182s	user 0.113s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":247,"lbm_read_time_us":10093,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28243,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:17:12.556969 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:12.602792 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.045s	user 0.032s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18052,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.603320 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:12.618691 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5935,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.619308 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:12.759366 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.140s	user 0.119s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":10083,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27859,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:12.760025 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=10.126437
I20260812 06:17:12.789266 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.029s	user 0.015s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12668,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.789726 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:12.804958 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.805428 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushMRSOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:12.831713 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushMRSOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.026s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":991,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1490,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:12.832362 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling LogGCOp(c1d704948173470396e64c62438f78c9): free 129320510 bytes of WAL
I20260812 06:17:12.832579 25670 log_reader.cc:385] T c1d704948173470396e64c62438f78c9: removed 13 log segments from log reader
I20260812 06:17:12.832695 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000015 (ops 69-73)
I20260812 06:17:12.832774 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000016 (ops 74-78)
I20260812 06:17:12.832829 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000017 (ops 79-83)
I20260812 06:17:12.832885 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000018 (ops 84-88)
I20260812 06:17:12.832932 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000019 (ops 89-93)
I20260812 06:17:12.832973 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000020 (ops 94-98)
I20260812 06:17:12.833017 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000021 (ops 99-102)
I20260812 06:17:12.833047 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000022 (ops 103-107)
I20260812 06:17:12.833127 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000023 (ops 108-112)
I20260812 06:17:12.833189 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000024 (ops 113-116)
I20260812 06:17:12.833236 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000025 (ops 117-121)
I20260812 06:17:12.833284 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000026 (ops 122-126)
I20260812 06:17:12.833328 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000027 (ops 127-131)
I20260812 06:17:12.861788 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: LogGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:12.862175 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=6.157687
I20260812 06:17:12.881636 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.019s	user 0.005s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8279,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:12.882165 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:13.050398 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.168s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918218,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":832,"lbm_read_time_us":12527,"lbm_reads_lt_1ms":669,"lbm_write_time_us":35091,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":26,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":99,"threads_started":1,"update_count":3000}
I20260812 06:17:13.052798 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9): 492 bytes on disk
I20260812 06:17:13.053635 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.054350 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:13.095919 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.041s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16573998,"delete_count":0,"lbm_write_time_us":17546,"lbm_writes_lt_1ms":407,"mutex_wait_us":238,"reinsert_count":0,"update_count":2020}
I20260812 06:17:13.096514 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:13.111882 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.015s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5032,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:13.112450 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:13.289212 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.177s	user 0.106s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1483,"lbm_read_time_us":10057,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27887,"lbm_writes_lt_1ms":543,"mutex_wait_us":323,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":2500}
I20260812 06:17:13.289809 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:13.326530 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.037s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16142,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.327183 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:13.340942 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5385,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.341447 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:13.475345 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.134s	user 0.090s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":8812,"lbm_reads_lt_1ms":568,"lbm_write_time_us":25740,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:13.475889 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:13.519917 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.044s	user 0.018s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17326,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.520382 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:13.529954 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3697,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.530431 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:13.679689 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.149s	user 0.103s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":9670,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28732,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:13.680225 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:13.722882 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.040s	user 0.029s	sys 0.008s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":16708,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.723389 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:13.733412 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.734046 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:13.884974 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.151s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1069,"lbm_read_time_us":10146,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26769,"lbm_writes_lt_1ms":543,"mutex_wait_us":337,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:17:13.885536 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:13.947342 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.062s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20747,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.947902 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:13.958453 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.959252 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:14.119385 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.160s	user 0.123s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":11807,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27237,"lbm_writes_lt_1ms":543,"mutex_wait_us":330,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2500}
I20260812 06:17:14.119899 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=14.095187
I20260812 06:17:14.167402 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.047s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.167936 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=2.188937
I20260812 06:17:14.183362 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.015s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5909,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.183801 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushMRSOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:14.214824 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushMRSOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":147,"dirs.run_wall_time_us":1106,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1948,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:14.215481 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling LogGCOp(c1d704948173470396e64c62438f78c9): free 132571598 bytes of WAL
I20260812 06:17:14.215705 25670 log_reader.cc:385] T c1d704948173470396e64c62438f78c9: removed 13 log segments from log reader
I20260812 06:17:14.215782 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000028 (ops 132-136)
I20260812 06:17:14.215830 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000029 (ops 137-140)
I20260812 06:17:14.215859 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000030 (ops 141-145)
I20260812 06:17:14.215891 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000031 (ops 146-150)
I20260812 06:17:14.215922 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000032 (ops 151-155)
I20260812 06:17:14.215950 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000033 (ops 156-160)
I20260812 06:17:14.215978 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000034 (ops 161-165)
I20260812 06:17:14.216006 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000035 (ops 166-170)
I20260812 06:17:14.216037 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000036 (ops 171-174)
I20260812 06:17:14.216068 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000037 (ops 175-179)
I20260812 06:17:14.216094 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000038 (ops 180-184)
I20260812 06:17:14.216122 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000039 (ops 185-189)
I20260812 06:17:14.216150 25670 log.cc:1079] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: Deleting log segment in path: /tmp/dist-test-taskVkyVJ0/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515424586082-25165-0/minicluster-data/ts-0-root/wals/c1d704948173470396e64c62438f78c9/wal-000000040 (ops 190-194)
I20260812 06:17:14.247037 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: LogGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.031s	user 0.003s	sys 0.026s Metrics: {}
I20260812 06:17:14.247453 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=5.165500
I20260812 06:17:14.262563 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":6605135,"delete_count":0,"lbm_write_time_us":6010,"lbm_writes_lt_1ms":164,"reinsert_count":0,"update_count":805}
I20260812 06:17:14.262969 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9): 482 bytes on disk
I20260812 06:17:14.263360 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: UndoDeltaBlockGCOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.263878 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:14.268913 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: FlushDeltaMemStoresOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.005s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1600127,"delete_count":0,"lbm_write_time_us":1477,"lbm_writes_lt_1ms":42,"reinsert_count":0,"update_count":195}
I20260812 06:17:14.269462 25772 maintenance_manager.cc:419] P e953fb6b2ffa479f9cb76a73e9552b9d: Scheduling MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9): perf score=1.000000
I20260812 06:17:14.299547 25165 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.480s	user 1.647s	sys 0.159s
I20260812 06:17:14.389623 25165 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.001s	sys 0.000s
I20260812 06:17:14.390259 25165 tablet_server.cc:179] TabletServer@127.24.147.65:0 shutting down...
I20260812 06:17:14.466233 25670 maintenance_manager.cc:643] P e953fb6b2ffa479f9cb76a73e9552b9d: MajorDeltaCompactionOp(c1d704948173470396e64c62438f78c9) complete. Timing: real 0.197s	user 0.120s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":224,"lbm_read_time_us":17577,"lbm_reads_lt_1ms":770,"lbm_write_time_us":31476,"lbm_writes_lt_1ms":743,"mutex_wait_us":71,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20480,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:17:14.468284 25165 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:14.468511 25165 tablet_replica.cc:333] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d: stopping tablet replica
I20260812 06:17:14.468653 25165 raft_consensus.cc:2243] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.468817 25165 raft_consensus.cc:2272] T c1d704948173470396e64c62438f78c9 P e953fb6b2ffa479f9cb76a73e9552b9d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.472820 25165 tablet_server.cc:196] TabletServer@127.24.147.65:0 shutdown complete.
I20260812 06:17:14.522532 25165 master.cc:562] Master@127.24.147.126:43217 shutting down...
I20260812 06:17:14.526486 25165 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:14.526640 25165 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:14.526713 25165 tablet_replica.cc:333] T 00000000000000000000000000000000 P 48c19bf78f45490ea166a3dad354814c: stopping tablet replica
I20260812 06:17:14.538774 25165 master.cc:584] Master@127.24.147.126:43217 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4987 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10016 ms total)

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