[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:22.477182  9513 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.74.126:37521
I20260812 06:18:22.478217  9513 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:22.478837  9513 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.486003  9521 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.486169  9513 server_base.cc:1061] running on GCE node
W20260812 06:18:22.486025  9519 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.486303  9518 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.486900  9513 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.487005  9513 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:22.487032  9513 hybrid_clock.cc:648] HybridClock initialized: now 1786515502487031 us; error 0 us; skew 500 ppm
I20260812 06:18:22.488976  9513 webserver.cc:533] Webserver started at http://127.9.74.126:37267/ using document root <none> and password file <none>
I20260812 06:18:22.489518  9513 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.489581  9513 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.489773  9513 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.491480  9513 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/master-0-root/instance:
uuid: "a490ae3ff7684f8fa4dcc83d97344734"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-8n49"
I20260812 06:18:22.495287  9513 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.004s
I20260812 06:18:22.497953  9528 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.499141  9513 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:22.499256  9513 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/master-0-root
uuid: "a490ae3ff7684f8fa4dcc83d97344734"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-8n49"
I20260812 06:18:22.499414  9513 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:22.510056  9513 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.510736  9513 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:22.510932  9513 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.519682  9513 rpc_server.cc:307] RPC server started. Bound to: 127.9.74.126:37521
I20260812 06:18:22.519678  9589 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.74.126:37521 every 8 connection(s)
I20260812 06:18:22.522192  9590 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.527724  9590 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: Bootstrap starting.
I20260812 06:18:22.530241  9590 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.531185  9590 log.cc:826] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:22.533143  9590 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: No bootstrap required, opened a new log
I20260812 06:18:22.536077  9590 raft_consensus.cc:359] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER }
I20260812 06:18:22.536257  9590 raft_consensus.cc:385] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.536331  9590 raft_consensus.cc:740] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a490ae3ff7684f8fa4dcc83d97344734, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.536996  9590 consensus_queue.cc:260] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [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: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER }
I20260812 06:18:22.537155  9590 raft_consensus.cc:399] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.537248  9590 raft_consensus.cc:493] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.537402  9590 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.538296  9590 raft_consensus.cc:515] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER }
I20260812 06:18:22.538767  9590 leader_election.cc:304] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [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: a490ae3ff7684f8fa4dcc83d97344734; no voters: 
I20260812 06:18:22.539140  9590 leader_election.cc:290] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.539351  9593 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.539601  9593 raft_consensus.cc:697] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 1 LEADER]: Becoming Leader. State: Replica: a490ae3ff7684f8fa4dcc83d97344734, State: Running, Role: LEADER
I20260812 06:18:22.540055  9593 consensus_queue.cc:237] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [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: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER }
I20260812 06:18:22.540292  9590 sys_catalog.cc:565] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:22.542253  9595 sys_catalog.cc:455] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [sys.catalog]: SysCatalogTable state changed. Reason: New leader a490ae3ff7684f8fa4dcc83d97344734. Latest consensus state: current_term: 1 leader_uuid: "a490ae3ff7684f8fa4dcc83d97344734" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER } }
I20260812 06:18:22.542433  9595 sys_catalog.cc:458] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.542282  9594 sys_catalog.cc:455] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a490ae3ff7684f8fa4dcc83d97344734" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a490ae3ff7684f8fa4dcc83d97344734" member_type: VOTER } }
I20260812 06:18:22.542686  9594 sys_catalog.cc:458] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:22.542851  9513 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:18:22.544927  9609 catalog_manager.cc:1594] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:18:22.544998  9609 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:18:22.545077  9608 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:22.545814  9608 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:22.550761  9608 catalog_manager.cc:1383] Generated new cluster ID: 6e2d01b0af3e4d16853dcab224ce0d9c
I20260812 06:18:22.550848  9608 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:22.557958  9608 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:22.559146  9608 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:22.588114  9608 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: Generated new TSK 0
I20260812 06:18:22.588984  9608 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:22.607829  9513 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:22.610944  9615 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.611090  9613 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:22.611300  9617 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:22.611392  9513 server_base.cc:1061] running on GCE node
I20260812 06:18:22.611696  9513 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:22.611756  9513 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:22.611779  9513 hybrid_clock.cc:648] HybridClock initialized: now 1786515502611779 us; error 0 us; skew 500 ppm
I20260812 06:18:22.612977  9513 webserver.cc:533] Webserver started at http://127.9.74.65:37079/ using document root <none> and password file <none>
I20260812 06:18:22.613181  9513 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:22.613250  9513 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:22.613344  9513 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:22.613849  9513 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/instance:
uuid: "1907cc20c1ab48e6974c43870c1cd7c9"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-8n49"
I20260812 06:18:22.615931  9513 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:22.617300  9624 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.617626  9513 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:22.617707  9513 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root
uuid: "1907cc20c1ab48e6974c43870c1cd7c9"
format_stamp: "Formatted at 2026-08-12 06:18:22 on dist-test-slave-8n49"
I20260812 06:18:22.617806  9513 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:22.625313  9513 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:22.625775  9513 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:22.626598  9513 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:22.627585  9513 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:22.627645  9513 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.627727  9513 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:22.627771  9513 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:22.635682  9513 rpc_server.cc:307] RPC server started. Bound to: 127.9.74.65:34703
I20260812 06:18:22.635715  9703 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.74.65:34703 every 8 connection(s)
I20260812 06:18:22.646371  9704 heartbeater.cc:344] Connected to a master server at 127.9.74.126:37521
I20260812 06:18:22.646688  9704 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:22.647187  9704 heartbeater.cc:507] Master 127.9.74.126:37521 requested a full tablet report, sending...
I20260812 06:18:22.649125  9547 ts_manager.cc:194] Registered new tserver with Master: 1907cc20c1ab48e6974c43870c1cd7c9 (127.9.74.65:34703)
I20260812 06:18:22.649243  9513 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012837256s
I20260812 06:18:22.650838  9547 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40946
I20260812 06:18:22.660764  9547 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40962:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:22.676304  9660 tablet_service.cc:1511] Processing CreateTablet for tablet 98778ff215c641529af73e988f455b11 (DEFAULT_TABLE table=heavy-update-compaction-test [id=5ac98648707d424b9ecb932c17d4b138]), partition=
I20260812 06:18:22.676856  9660 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 98778ff215c641529af73e988f455b11. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:22.679049  9716 tablet_bootstrap.cc:492] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Bootstrap starting.
I20260812 06:18:22.680068  9716 tablet_bootstrap.cc:654] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:22.681229  9716 tablet_bootstrap.cc:492] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: No bootstrap required, opened a new log
I20260812 06:18:22.681318  9716 ts_tablet_manager.cc:1403] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:22.681779  9716 raft_consensus.cc:359] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1907cc20c1ab48e6974c43870c1cd7c9" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 34703 } }
I20260812 06:18:22.681885  9716 raft_consensus.cc:385] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:22.681908  9716 raft_consensus.cc:740] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1907cc20c1ab48e6974c43870c1cd7c9, State: Initialized, Role: FOLLOWER
I20260812 06:18:22.682060  9716 consensus_queue.cc:260] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [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: "1907cc20c1ab48e6974c43870c1cd7c9" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 34703 } }
I20260812 06:18:22.682135  9716 raft_consensus.cc:399] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:22.682161  9716 raft_consensus.cc:493] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:22.682238  9716 raft_consensus.cc:3060] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:22.683035  9716 raft_consensus.cc:515] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1907cc20c1ab48e6974c43870c1cd7c9" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 34703 } }
I20260812 06:18:22.683199  9716 leader_election.cc:304] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [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: 1907cc20c1ab48e6974c43870c1cd7c9; no voters: 
I20260812 06:18:22.683435  9716 leader_election.cc:290] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:22.683583  9718 raft_consensus.cc:2804] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:22.683888  9718 raft_consensus.cc:697] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 1 LEADER]: Becoming Leader. State: Replica: 1907cc20c1ab48e6974c43870c1cd7c9, State: Running, Role: LEADER
I20260812 06:18:22.684067  9718 consensus_queue.cc:237] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [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: "1907cc20c1ab48e6974c43870c1cd7c9" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 34703 } }
I20260812 06:18:22.684291  9704 heartbeater.cc:499] Master 127.9.74.126:37521 was elected leader, sending a full tablet report...
I20260812 06:18:22.683880  9716 ts_tablet_manager.cc:1434] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:22.687076  9547 catalog_manager.cc:5719] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1907cc20c1ab48e6974c43870c1cd7c9 (127.9.74.65). New cstate: current_term: 1 leader_uuid: "1907cc20c1ab48e6974c43870c1cd7c9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1907cc20c1ab48e6974c43870c1cd7c9" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 34703 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:22.765847  9513 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.068s	user 0.022s	sys 0.013s
I20260812 06:18:22.887149  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushMRSOp(98778ff215c641529af73e988f455b11): perf score=15.086190
I20260812 06:18:23.029584  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushMRSOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.142s	user 0.113s	sys 0.028s Metrics: {"bytes_written":8615325,"cfile_init":1,"compiler_manager_pool.queue_time_us":232,"delete_count":0,"dirs.queue_time_us":43,"dirs.run_cpu_time_us":200,"dirs.run_wall_time_us":1526,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":32285,"lbm_writes_lt_1ms":567,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":156,"threads_started":1,"update_count":1050}
I20260812 06:18:23.030675  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling LogGCOp(98778ff215c641529af73e988f455b11): free 11976772 bytes of WAL
I20260812 06:18:23.030984  9632 log_reader.cc:385] T 98778ff215c641529af73e988f455b11: removed 1 log segments from log reader
I20260812 06:18:23.031076  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000001 (ops 1-6)
I20260812 06:18:23.033543  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: LogGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:23.033907  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11): 12308959 bytes on disk
I20260812 06:18:23.034489  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:18:23.034901  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:23.053655  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.019s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4820,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:23.054294  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:23.175805  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.121s	user 0.098s	sys 0.020s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16528893,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":949,"lbm_read_time_us":7583,"lbm_reads_lt_1ms":360,"lbm_write_time_us":23740,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":323,"threads_started":5,"update_count":1500}
I20260812 06:18:23.176396  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:23.226121  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.050s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17089,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.226606  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:23.237668  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.238281  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:23.375358  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.137s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":9218,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23974,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:18:23.376912  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:23.432808  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.056s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16046,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.433445  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:23.450785  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6556,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.451357  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:23.602916  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.151s	user 0.096s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1232,"lbm_read_time_us":12593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23899,"lbm_writes_lt_1ms":443,"mutex_wait_us":351,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.603729  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:23.650216  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.046s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16017,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.650763  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:23.662204  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4000,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.662700  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:23.788720  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.126s	user 0.102s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":201,"lbm_read_time_us":8430,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23107,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":2000}
I20260812 06:18:23.789391  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:23.830904  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.041s	user 0.022s	sys 0.010s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14938,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:23.831494  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:23.844357  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:23.844928  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:23.972892  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.128s	user 0.107s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1667,"lbm_read_time_us":9095,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25219,"lbm_writes_lt_1ms":443,"mutex_wait_us":404,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:23.973548  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:24.023362  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.050s	user 0.024s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":18891,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.023906  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:24.034911  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.035389  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:24.196743  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.161s	user 0.130s	sys 0.022s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1281,"lbm_read_time_us":10759,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25533,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:24.197403  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:24.243995  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.046s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14329,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.244516  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:24.255659  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.256294  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:24.383874  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.127s	user 0.095s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1408,"lbm_read_time_us":8648,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26116,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:24.384452  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:24.433682  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.049s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16835,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:24.434182  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:24.445559  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.446341  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushMRSOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:24.478093  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushMRSOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1702,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2026,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:24.479009  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling LogGCOp(98778ff215c641529af73e988f455b11): free 133024350 bytes of WAL
I20260812 06:18:24.479264  9632 log_reader.cc:385] T 98778ff215c641529af73e988f455b11: removed 13 log segments from log reader
I20260812 06:18:24.479312  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000002 (ops 7-11)
I20260812 06:18:24.479344  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000003 (ops 12-16)
I20260812 06:18:24.479414  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000004 (ops 17-21)
I20260812 06:18:24.479488  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000005 (ops 22-26)
I20260812 06:18:24.479539  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000006 (ops 27-31)
I20260812 06:18:24.479596  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000007 (ops 32-36)
I20260812 06:18:24.479640  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000008 (ops 37-41)
I20260812 06:18:24.479687  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000009 (ops 42-46)
I20260812 06:18:24.479733  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000010 (ops 47-51)
I20260812 06:18:24.479777  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000011 (ops 52-56)
I20260812 06:18:24.479820  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000012 (ops 57-61)
I20260812 06:18:24.479861  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000013 (ops 62-66)
I20260812 06:18:24.479902  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000014 (ops 67-70)
I20260812 06:18:24.513356  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: LogGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:18:24.514007  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11): 483 bytes on disk
I20260812 06:18:24.514585  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:24.515178  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=4.173312
I20260812 06:18:24.532821  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":5907728,"delete_count":0,"lbm_write_time_us":6981,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:24.533398  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=1.196750
I20260812 06:18:24.544018  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":3487,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:24.544663  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:24.730530  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.186s	user 0.128s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":317,"lbm_read_time_us":13493,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35110,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":75904,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:24.731287  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:24.787771  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.056s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":21752,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:24.788234  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:24.800536  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:24.801226  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:24.972071  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.171s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":697,"lbm_read_time_us":11196,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30152,"lbm_writes_lt_1ms":543,"mutex_wait_us":307,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":27392,"update_count":2500}
I20260812 06:18:24.972886  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:25.036149  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.063s	user 0.040s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21192,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.036828  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:25.047971  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.048710  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:25.222970  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.174s	user 0.129s	sys 0.037s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":11559,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29321,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":80896,"update_count":2500}
I20260812 06:18:25.223677  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:25.279528  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.056s	user 0.036s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19460,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.280105  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:25.296186  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.296880  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:25.482105  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.185s	user 0.116s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":211,"lbm_read_time_us":12928,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29645,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:18:25.482800  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:25.547201  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.064s	user 0.046s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22528,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:25.547780  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:25.558992  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:25.559587  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:25.729768  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.170s	user 0.134s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":545,"lbm_read_time_us":12939,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28857,"lbm_writes_lt_1ms":543,"mutex_wait_us":106,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:25.732206  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=11.118625
I20260812 06:18:25.764760  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.032s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13683,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:25.765544  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:25.781688  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5427,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:25.782249  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:25.950855  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.168s	user 0.106s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":582,"lbm_read_time_us":9124,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24029,"lbm_writes_lt_1ms":443,"mutex_wait_us":282,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:18:25.951741  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:26.001730  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.050s	user 0.041s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:26.002311  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:26.019464  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.019994  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushMRSOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:26.057631  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushMRSOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.037s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1648,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1782,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:26.058454  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling LogGCOp(98778ff215c641529af73e988f455b11): free 125163547 bytes of WAL
I20260812 06:18:26.058714  9632 log_reader.cc:385] T 98778ff215c641529af73e988f455b11: removed 13 log segments from log reader
I20260812 06:18:26.058763  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000015 (ops 71-75)
I20260812 06:18:26.058795  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000016 (ops 76-80)
I20260812 06:18:26.058853  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000017 (ops 81-84)
I20260812 06:18:26.058905  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000018 (ops 85-89)
I20260812 06:18:26.058938  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000019 (ops 90-94)
I20260812 06:18:26.058979  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000020 (ops 95-98)
I20260812 06:18:26.059020  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000021 (ops 99-103)
I20260812 06:18:26.059064  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000022 (ops 104-108)
I20260812 06:18:26.059108  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000023 (ops 109-112)
I20260812 06:18:26.059154  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000024 (ops 113-117)
I20260812 06:18:26.059197  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000025 (ops 118-122)
I20260812 06:18:26.059245  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000026 (ops 123-126)
I20260812 06:18:26.059291  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000027 (ops 127-131)
I20260812 06:18:26.087899  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: LogGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.029s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:18:26.088356  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11): 492 bytes on disk
I20260812 06:18:26.088864  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:26.089461  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=6.157687
I20260812 06:18:26.132791  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.043s	user 0.023s	sys 0.006s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9190,"lbm_writes_lt_1ms":203,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1000}
I20260812 06:18:26.133419  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling LogGCOp(98778ff215c641529af73e988f455b11): free 12018006 bytes of WAL
I20260812 06:18:26.133675  9632 log_reader.cc:385] T 98778ff215c641529af73e988f455b11: removed 1 log segments from log reader
I20260812 06:18:26.133733  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000028 (ops 132-136)
I20260812 06:18:26.136782  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: LogGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:26.137171  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:26.154376  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6402,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.154956  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:26.413632  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.258s	user 0.185s	sys 0.068s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37041197,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":714,"lbm_read_time_us":16393,"lbm_reads_lt_1ms":874,"lbm_write_time_us":43160,"lbm_writes_lt_1ms":843,"mutex_wait_us":298,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":97,"threads_started":1,"update_count":4000}
I20260812 06:18:26.414409  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=18.063937
I20260812 06:18:26.496359  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.080s	user 0.030s	sys 0.035s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":31861,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:18:26.496984  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:26.508543  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:26.509088  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:26.722759  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.213s	user 0.145s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836139,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":13779,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35523,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":21504,"update_count":3000}
I20260812 06:18:26.723461  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=15.087375
I20260812 06:18:26.779533  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.056s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16820144,"delete_count":0,"lbm_write_time_us":25049,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:26.780313  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:26.796782  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4688,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:26.797386  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:26.968772  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.171s	user 0.118s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733712,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1541,"lbm_read_time_us":12852,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29177,"lbm_writes_lt_1ms":543,"mutex_wait_us":465,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:18:26.969477  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:27.017727  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.048s	user 0.038s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20357,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.018503  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:27.031289  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4698,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.031915  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:27.214931  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.183s	user 0.110s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":403,"lbm_read_time_us":12589,"lbm_reads_lt_1ms":568,"lbm_write_time_us":33376,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":2500}
I20260812 06:18:27.215704  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:27.278636  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.063s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20661,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.279285  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:27.290277  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.290896  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:27.468577  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.177s	user 0.121s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":11963,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30433,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:18:27.469355  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=10.126437
I20260812 06:18:27.514955  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.045s	user 0.018s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18152,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:27.515841  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:27.542953  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.027s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.543421  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:27.562781  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.019s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4047,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:27.563596  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushMRSOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:27.604468  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushMRSOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.041s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1422,"drs_written":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1588,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:27.605235  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling LogGCOp(98778ff215c641529af73e988f455b11): free 112692556 bytes of WAL
I20260812 06:18:27.605468  9632 log_reader.cc:385] T 98778ff215c641529af73e988f455b11: removed 11 log segments from log reader
I20260812 06:18:27.605521  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000029 (ops 137-141)
I20260812 06:18:27.605551  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000030 (ops 142-146)
I20260812 06:18:27.605612  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000031 (ops 147-151)
I20260812 06:18:27.605660  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000032 (ops 152-156)
I20260812 06:18:27.605702  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000033 (ops 157-161)
I20260812 06:18:27.605762  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000034 (ops 162-166)
I20260812 06:18:27.605801  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000035 (ops 167-171)
I20260812 06:18:27.605839  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000036 (ops 172-176)
I20260812 06:18:27.605877  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000037 (ops 177-181)
I20260812 06:18:27.605916  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000038 (ops 182-186)
I20260812 06:18:27.605953  9632 log.cc:1079] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/98778ff215c641529af73e988f455b11/wal-000000039 (ops 187-191)
I20260812 06:18:27.630007  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: LogGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:27.630390  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=3.181125
I20260812 06:18:27.653769  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.023s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6607,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:27.654310  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=2.188937
I20260812 06:18:27.663957  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3503,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:27.664546  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:27.884473  9513 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.119s	user 1.845s	sys 0.167s
I20260812 06:18:27.905403  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.241s	user 0.148s	sys 0.092s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938894,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15520,"lbm_reads_lt_1ms":771,"lbm_write_time_us":42418,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3500}
I20260812 06:18:27.906203  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11): 448 bytes on disk
I20260812 06:18:27.906687  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: UndoDeltaBlockGCOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:27.907267  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11): perf score=14.095187
I20260812 06:18:27.943339  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: FlushDeltaMemStoresOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.036s	user 0.019s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17338,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:27.943842  9705 maintenance_manager.cc:419] P 1907cc20c1ab48e6974c43870c1cd7c9: Scheduling MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11): perf score=1.000000
I20260812 06:18:28.000006  9513 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.115s	user 0.001s	sys 0.000s
I20260812 06:18:28.000766  9513 tablet_server.cc:179] TabletServer@127.9.74.65:0 shutting down...
I20260812 06:18:28.071514  9632 maintenance_manager.cc:643] P 1907cc20c1ab48e6974c43870c1cd7c9: MajorDeltaCompactionOp(98778ff215c641529af73e988f455b11) complete. Timing: real 0.127s	user 0.083s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631192,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":602,"lbm_read_time_us":9209,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25538,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:18:28.072269  9513 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:28.072767  9513 tablet_replica.cc:333] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9: stopping tablet replica
I20260812 06:18:28.073026  9513 raft_consensus.cc:2243] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.073269  9513 raft_consensus.cc:2272] T 98778ff215c641529af73e988f455b11 P 1907cc20c1ab48e6974c43870c1cd7c9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.090694  9513 tablet_server.cc:196] TabletServer@127.9.74.65:0 shutdown complete.
I20260812 06:18:28.121546  9513 master.cc:562] Master@127.9.74.126:37521 shutting down...
I20260812 06:18:28.126315  9513 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:28.126518  9513 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:28.126627  9513 tablet_replica.cc:333] T 00000000000000000000000000000000 P a490ae3ff7684f8fa4dcc83d97344734: stopping tablet replica
I20260812 06:18:28.139477  9513 master.cc:584] Master@127.9.74.126:37521 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5749 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:28.239802  9513 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.74.126:38395
I20260812 06:18:28.240243  9513 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.242897  9745 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:28.243008  9747 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.243068  9513 server_base.cc:1061] running on GCE node
W20260812 06:18:28.242878  9744 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.243319  9513 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.243361  9513 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:28.243377  9513 hybrid_clock.cc:648] HybridClock initialized: now 1786515508243377 us; error 0 us; skew 500 ppm
I20260812 06:18:28.244217  9513 webserver.cc:533] Webserver started at http://127.9.74.126:33409/ using document root <none> and password file <none>
I20260812 06:18:28.244354  9513 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.244400  9513 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.244458  9513 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.244910  9513 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/master-0-root/instance:
uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-8n49"
I20260812 06:18:28.246354  9513 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:28.247231  9752 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.247473  9513 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:28.247545  9513 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/master-0-root
uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-8n49"
I20260812 06:18:28.247601  9513 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:28.274655  9513 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.275072  9513 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.279601  9513 rpc_server.cc:307] RPC server started. Bound to: 127.9.74.126:38395
I20260812 06:18:28.279637  9811 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.74.126:38395 every 8 connection(s)
I20260812 06:18:28.280510  9812 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.282418  9812 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9: Bootstrap starting.
I20260812 06:18:28.283216  9812 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.284323  9812 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9: No bootstrap required, opened a new log
I20260812 06:18:28.284857  9812 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER }
I20260812 06:18:28.284955  9812 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.284979  9812 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8d3ffc4d8d1c4ba99b728af4fc8aaeb9, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.285138  9812 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [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: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER }
I20260812 06:18:28.285226  9812 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.285252  9812 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.285310  9812 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.286046  9812 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER }
I20260812 06:18:28.286162  9812 leader_election.cc:304] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [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: 8d3ffc4d8d1c4ba99b728af4fc8aaeb9; no voters: 
I20260812 06:18:28.286422  9812 leader_election.cc:290] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.286639  9815 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.286856  9815 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 1 LEADER]: Becoming Leader. State: Replica: 8d3ffc4d8d1c4ba99b728af4fc8aaeb9, State: Running, Role: LEADER
I20260812 06:18:28.286927  9812 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:28.287019  9815 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [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: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER }
I20260812 06:18:28.287428  9818 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8d3ffc4d8d1c4ba99b728af4fc8aaeb9. Latest consensus state: current_term: 1 leader_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER } }
I20260812 06:18:28.287536  9818 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.287986  9816 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d3ffc4d8d1c4ba99b728af4fc8aaeb9" member_type: VOTER } }
I20260812 06:18:28.288131  9816 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:28.288259  9821 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:28.289002  9821 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:28.289281  9513 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:28.290946  9821 catalog_manager.cc:1383] Generated new cluster ID: 58b083f2e7894c51b26a11b954e392fc
I20260812 06:18:28.291013  9821 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:28.299317  9821 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:28.299930  9821 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:28.305545  9821 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9: Generated new TSK 0
I20260812 06:18:28.305756  9821 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:28.321821  9513 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:28.324184  9842 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.324294  9513 server_base.cc:1061] running on GCE node
W20260812 06:18:28.324178  9840 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:28.324172  9839 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:28.324690  9513 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:28.324736  9513 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:28.324752  9513 hybrid_clock.cc:648] HybridClock initialized: now 1786515508324752 us; error 0 us; skew 500 ppm
I20260812 06:18:28.325654  9513 webserver.cc:533] Webserver started at http://127.9.74.65:35875/ using document root <none> and password file <none>
I20260812 06:18:28.325805  9513 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:28.325852  9513 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:28.325924  9513 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:28.326292  9513 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/instance:
uuid: "7a94fb4ff2cb418aba1569be13257ce8"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-8n49"
I20260812 06:18:28.327883  9513 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:28.328989  9849 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.329365  9513 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:28.329480  9513 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root
uuid: "7a94fb4ff2cb418aba1569be13257ce8"
format_stamp: "Formatted at 2026-08-12 06:18:28 on dist-test-slave-8n49"
I20260812 06:18:28.329581  9513 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:28.349525  9513 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:28.349980  9513 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:28.350308  9513 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:28.350811  9513 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:28.350873  9513 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.350937  9513 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:28.350972  9513 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:28.355578  9513 rpc_server.cc:307] RPC server started. Bound to: 127.9.74.65:37205
I20260812 06:18:28.355609  9918 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.74.65:37205 every 8 connection(s)
I20260812 06:18:28.364073  9919 heartbeater.cc:344] Connected to a master server at 127.9.74.126:38395
I20260812 06:18:28.364213  9919 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:28.364468  9919 heartbeater.cc:507] Master 127.9.74.126:38395 requested a full tablet report, sending...
I20260812 06:18:28.365243  9773 ts_manager.cc:194] Registered new tserver with Master: 7a94fb4ff2cb418aba1569be13257ce8 (127.9.74.65:37205)
I20260812 06:18:28.365983  9773 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48184
I20260812 06:18:28.366314  9513 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010073154s
I20260812 06:18:28.373800  9773 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48200:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:28.383481  9879 tablet_service.cc:1511] Processing CreateTablet for tablet fd8df010305842bc92eecb5677623d91 (DEFAULT_TABLE table=heavy-update-compaction-test [id=496455e2daf04adda1ec9c228c5a5eb0]), partition=
I20260812 06:18:28.383761  9879 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fd8df010305842bc92eecb5677623d91. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:28.386056  9931 tablet_bootstrap.cc:492] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Bootstrap starting.
I20260812 06:18:28.386936  9931 tablet_bootstrap.cc:654] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:28.388222  9931 tablet_bootstrap.cc:492] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: No bootstrap required, opened a new log
I20260812 06:18:28.388350  9931 ts_tablet_manager.cc:1403] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:28.388926  9931 raft_consensus.cc:359] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a94fb4ff2cb418aba1569be13257ce8" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 37205 } }
I20260812 06:18:28.389047  9931 raft_consensus.cc:385] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:28.389099  9931 raft_consensus.cc:740] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7a94fb4ff2cb418aba1569be13257ce8, State: Initialized, Role: FOLLOWER
I20260812 06:18:28.389249  9931 consensus_queue.cc:260] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [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: "7a94fb4ff2cb418aba1569be13257ce8" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 37205 } }
I20260812 06:18:28.389345  9931 raft_consensus.cc:399] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:28.389392  9931 raft_consensus.cc:493] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:28.389449  9931 raft_consensus.cc:3060] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:28.390202  9931 raft_consensus.cc:515] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a94fb4ff2cb418aba1569be13257ce8" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 37205 } }
I20260812 06:18:28.390372  9931 leader_election.cc:304] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [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: 7a94fb4ff2cb418aba1569be13257ce8; no voters: 
I20260812 06:18:28.390599  9931 leader_election.cc:290] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:28.390831  9934 raft_consensus.cc:2804] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:28.390944  9934 raft_consensus.cc:697] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 1 LEADER]: Becoming Leader. State: Replica: 7a94fb4ff2cb418aba1569be13257ce8, State: Running, Role: LEADER
I20260812 06:18:28.391003  9931 ts_tablet_manager.cc:1434] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:28.391022  9919 heartbeater.cc:499] Master 127.9.74.126:38395 was elected leader, sending a full tablet report...
I20260812 06:18:28.391126  9934 consensus_queue.cc:237] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [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: "7a94fb4ff2cb418aba1569be13257ce8" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 37205 } }
I20260812 06:18:28.392700  9772 catalog_manager.cc:5719] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 reported cstate change: term changed from 0 to 1, leader changed from <none> to 7a94fb4ff2cb418aba1569be13257ce8 (127.9.74.65). New cstate: current_term: 1 leader_uuid: "7a94fb4ff2cb418aba1569be13257ce8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7a94fb4ff2cb418aba1569be13257ce8" member_type: VOTER last_known_addr { host: "127.9.74.65" port: 37205 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:28.460446  9513 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.008s	sys 0.016s
I20260812 06:18:28.606782  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushMRSOp(fd8df010305842bc92eecb5677623d91): perf score=19.054940
I20260812 06:18:28.762665  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushMRSOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.156s	user 0.102s	sys 0.049s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":874,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39915,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:28.763312  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling LogGCOp(fd8df010305842bc92eecb5677623d91): free 20743880 bytes of WAL
I20260812 06:18:28.763546  9854 log_reader.cc:385] T fd8df010305842bc92eecb5677623d91: removed 2 log segments from log reader
I20260812 06:18:28.763593  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000001 (ops 1-6)
I20260812 06:18:28.763624  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000002 (ops 7-11)
I20260812 06:18:28.767694  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: LogGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:28.768082  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91): 16411393 bytes on disk
I20260812 06:18:28.768529  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:28.769101  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:28.787309  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.018s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4828,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:28.788252  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:28.958298  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.170s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":859,"lbm_read_time_us":10250,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23906,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":359,"threads_started":5,"update_count":2000}
I20260812 06:18:28.959007  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:29.004302  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.045s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19563,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.004769  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:29.015214  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3930,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.016784  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:29.184440  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.167s	user 0.134s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":11207,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29893,"lbm_writes_lt_1ms":543,"mutex_wait_us":251,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2500}
I20260812 06:18:29.185236  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:29.235899  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.050s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21071,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.236416  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:29.246980  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.247568  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:29.414769  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.167s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":11729,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31341,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:18:29.415567  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=11.118625
I20260812 06:18:29.449815  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.034s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14400,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:29.450542  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:29.475327  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.025s	user 0.008s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7223,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:29.475850  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:29.607765  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.132s	user 0.099s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":521,"lbm_read_time_us":9389,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25412,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:18:29.608760  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=10.126437
I20260812 06:18:29.654507  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14774,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.655112  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:29.667343  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.667865  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:29.826494  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.158s	user 0.118s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1310,"lbm_read_time_us":10545,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25841,"lbm_writes_lt_1ms":443,"mutex_wait_us":331,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:29.827194  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=10.126437
I20260812 06:18:29.867712  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15731,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:29.868222  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:29.883984  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5752,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:29.884615  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:30.019805  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.135s	user 0.102s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":276,"lbm_read_time_us":8722,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25805,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":32640,"update_count":2000}
I20260812 06:18:30.020489  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=10.126437
I20260812 06:18:30.068847  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.048s	user 0.026s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21270,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.069386  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.079768  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4023,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.080276  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushMRSOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:30.112516  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushMRSOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.032s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":297,"dirs.run_wall_time_us":1416,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1651,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:30.113230  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling LogGCOp(fd8df010305842bc92eecb5677623d91): free 120553376 bytes of WAL
I20260812 06:18:30.113505  9854 log_reader.cc:385] T fd8df010305842bc92eecb5677623d91: removed 12 log segments from log reader
I20260812 06:18:30.113569  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000003 (ops 12-16)
I20260812 06:18:30.113607  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000004 (ops 17-20)
I20260812 06:18:30.113631  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000005 (ops 21-25)
I20260812 06:18:30.113652  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000006 (ops 26-30)
I20260812 06:18:30.113677  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000007 (ops 31-35)
I20260812 06:18:30.113716  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000008 (ops 36-40)
I20260812 06:18:30.113750  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000009 (ops 41-45)
I20260812 06:18:30.113773  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000010 (ops 46-50)
I20260812 06:18:30.113795  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000011 (ops 51-54)
I20260812 06:18:30.113826  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000012 (ops 55-59)
I20260812 06:18:30.113857  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000013 (ops 60-64)
I20260812 06:18:30.113890  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000014 (ops 65-69)
I20260812 06:18:30.143337  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: LogGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:30.143784  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91): 472 bytes on disk
I20260812 06:18:30.144346  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:18:30.144848  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.169137  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.024s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.169641  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.184242  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5583,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.184808  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:30.367599  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.182s	user 0.146s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":417,"lbm_read_time_us":13877,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36996,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":19,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":10752,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:18:30.368345  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:30.419323  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.051s	user 0.034s	sys 0.008s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19575,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.419813  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.435882  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.436487  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:30.585052  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.148s	user 0.113s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":261,"lbm_read_time_us":11379,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27951,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18304,"update_count":2500}
I20260812 06:18:30.587275  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=11.118625
I20260812 06:18:30.622787  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.035s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12758763,"delete_count":0,"lbm_write_time_us":15414,"lbm_writes_lt_1ms":314,"reinsert_count":0,"update_count":1555}
I20260812 06:18:30.623284  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.647599  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.024s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":4714,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:18:30.648044  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.658511  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.658942  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:30.847972  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.189s	user 0.121s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":345,"lbm_read_time_us":12195,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29350,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:30.848573  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:30.917229  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.068s	user 0.025s	sys 0.033s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26277,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:30.917718  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:30.927999  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3834,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.928614  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:31.109318  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.180s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11380,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30946,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:18:31.110019  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:31.163904  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.054s	user 0.035s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19331,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.164472  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:31.175350  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4270,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.175800  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:31.355759  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.180s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1645,"lbm_read_time_us":12155,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28857,"lbm_writes_lt_1ms":543,"mutex_wait_us":1084,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:31.356309  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:31.421571  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.065s	user 0.046s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23543,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.422087  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:31.433427  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.433921  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:31.617986  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.184s	user 0.122s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":12524,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32617,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30464,"update_count":2500}
I20260812 06:18:31.621353  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=10.126437
I20260812 06:18:31.656041  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.034s	user 0.017s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.656903  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:31.681892  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5314,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.682401  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:31.702111  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.702688  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushMRSOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:31.741361  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushMRSOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.038s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":188,"dirs.run_wall_time_us":1549,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1583,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:31.742048  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling LogGCOp(fd8df010305842bc92eecb5677623d91): free 133024338 bytes of WAL
I20260812 06:18:31.742307  9854 log_reader.cc:385] T fd8df010305842bc92eecb5677623d91: removed 13 log segments from log reader
I20260812 06:18:31.742379  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000015 (ops 70-74)
I20260812 06:18:31.742429  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000016 (ops 75-79)
I20260812 06:18:31.742488  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000017 (ops 80-84)
I20260812 06:18:31.742532  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000018 (ops 85-89)
I20260812 06:18:31.742573  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000019 (ops 90-94)
I20260812 06:18:31.742614  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000020 (ops 95-98)
I20260812 06:18:31.742654  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000021 (ops 99-103)
I20260812 06:18:31.742694  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000022 (ops 104-108)
I20260812 06:18:31.742734  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000023 (ops 109-113)
I20260812 06:18:31.742774  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000024 (ops 114-118)
I20260812 06:18:31.742813  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000025 (ops 119-123)
I20260812 06:18:31.742852  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000026 (ops 124-128)
I20260812 06:18:31.742892  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000027 (ops 129-133)
I20260812 06:18:31.770138  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: LogGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:31.770547  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91): 493 bytes on disk
I20260812 06:18:31.770992  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.771636  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=3.181125
I20260812 06:18:31.787447  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.016s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4720,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:31.787961  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:31.798570  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3592,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:31.799190  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:32.026284  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.227s	user 0.136s	sys 0.090s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979859,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":604,"lbm_read_time_us":14397,"lbm_reads_lt_1ms":775,"lbm_write_time_us":38116,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:32.027598  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=16.079562
I20260812 06:18:32.095958  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.068s	user 0.033s	sys 0.017s Metrics: {"bytes_written":17640623,"delete_count":0,"lbm_write_time_us":23468,"lbm_writes_lt_1ms":433,"reinsert_count":0,"update_count":2150}
I20260812 06:18:32.096491  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=5.165500
I20260812 06:18:32.118744  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.022s	user 0.011s	sys 0.009s Metrics: {"bytes_written":6974357,"delete_count":0,"lbm_write_time_us":8904,"lbm_writes_lt_1ms":173,"reinsert_count":0,"update_count":850}
I20260812 06:18:32.119309  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:32.337963  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.218s	user 0.133s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":14382,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33826,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":3000}
I20260812 06:18:32.338780  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=18.063937
I20260812 06:18:32.409309  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.070s	user 0.023s	sys 0.044s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28677,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:32.409855  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:32.421226  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.421728  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:32.618374  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.196s	user 0.137s	sys 0.060s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":11726,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34709,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":78976,"update_count":3000}
I20260812 06:18:32.619240  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:32.685490  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.066s	user 0.030s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26932,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.686084  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:32.699870  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.700449  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:32.883100  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.182s	user 0.116s	sys 0.065s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1231,"lbm_read_time_us":12204,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32364,"lbm_writes_lt_1ms":543,"mutex_wait_us":420,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:32.883949  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=15.087375
I20260812 06:18:32.941391  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.057s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":25767,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:32.941951  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:32.954550  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:32.955098  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:33.125543  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.170s	user 0.119s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":990,"lbm_read_time_us":11340,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27113,"lbm_writes_lt_1ms":543,"mutex_wait_us":255,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:18:33.126353  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=14.095187
I20260812 06:18:33.185338  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.059s	user 0.015s	sys 0.043s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21465,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.186070  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:33.197540  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4529,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.198057  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushMRSOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:33.240458  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushMRSOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.042s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1835,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1519,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:33.241266  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling LogGCOp(fd8df010305842bc92eecb5677623d91): free 120100640 bytes of WAL
I20260812 06:18:33.241498  9854 log_reader.cc:385] T fd8df010305842bc92eecb5677623d91: removed 12 log segments from log reader
I20260812 06:18:33.241544  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000028 (ops 134-138)
I20260812 06:18:33.241570  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000029 (ops 139-142)
I20260812 06:18:33.241640  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000030 (ops 143-147)
I20260812 06:18:33.241683  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000031 (ops 148-152)
I20260812 06:18:33.241729  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000032 (ops 153-157)
I20260812 06:18:33.241772  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000033 (ops 158-162)
I20260812 06:18:33.241815  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000034 (ops 163-166)
I20260812 06:18:33.241853  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000035 (ops 167-171)
I20260812 06:18:33.241896  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000036 (ops 172-176)
I20260812 06:18:33.241935  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000037 (ops 177-181)
I20260812 06:18:33.241972  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000038 (ops 182-186)
I20260812 06:18:33.242012  9854 log.cc:1079] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: Deleting log segment in path: /tmp/dist-test-taskAx2i7_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515502466264-9513-0/minicluster-data/ts-0-root/wals/fd8df010305842bc92eecb5677623d91/wal-000000039 (ops 187-190)
I20260812 06:18:33.267581  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: LogGCOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:33.268121  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:33.290419  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.022s	user 0.003s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.290872  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91): 462 bytes on disk
I20260812 06:18:33.291272  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: UndoDeltaBlockGCOp(fd8df010305842bc92eecb5677623d91) 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:18:33.291822  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=2.188937
I20260812 06:18:33.302292  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3919,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.302790  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91): perf score=1.000000
I20260812 06:18:33.439018  9513 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.978s	user 1.891s	sys 0.175s
I20260812 06:18:33.519011  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: MajorDeltaCompactionOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.216s	user 0.122s	sys 0.093s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1495,"lbm_read_time_us":14721,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37777,"lbm_writes_lt_1ms":743,"mutex_wait_us":484,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10368,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:18:33.519685  9920 maintenance_manager.cc:419] P 7a94fb4ff2cb418aba1569be13257ce8: Scheduling FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91): perf score=10.126437
I20260812 06:18:33.531180  9513 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.001s	sys 0.000s
I20260812 06:18:33.531656  9513 tablet_server.cc:179] TabletServer@127.9.74.65:0 shutting down...
I20260812 06:18:33.553083  9854 maintenance_manager.cc:643] P 7a94fb4ff2cb418aba1569be13257ce8: FlushDeltaMemStoresOp(fd8df010305842bc92eecb5677623d91) complete. Timing: real 0.033s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14449,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.553617  9513 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:33.554867  9513 tablet_replica.cc:333] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8: stopping tablet replica
I20260812 06:18:33.554977  9513 raft_consensus.cc:2243] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.555128  9513 raft_consensus.cc:2272] T fd8df010305842bc92eecb5677623d91 P 7a94fb4ff2cb418aba1569be13257ce8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.558879  9513 tablet_server.cc:196] TabletServer@127.9.74.65:0 shutdown complete.
I20260812 06:18:33.577452  9513 master.cc:562] Master@127.9.74.126:38395 shutting down...
I20260812 06:18:33.580818  9513 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:33.581017  9513 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:33.581097  9513 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8d3ffc4d8d1c4ba99b728af4fc8aaeb9: stopping tablet replica
I20260812 06:18:33.593504  9513 master.cc:584] Master@127.9.74.126:38395 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5451 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11201 ms total)

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