[==========] 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:19:13.285336  3681 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.152.126:34317
I20260812 06:19:13.286340  3681 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:19:13.286971  3681 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:13.293574  3681 server_base.cc:1061] running on GCE node
W20260812 06:19:13.293742  3690 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:19:13.294009  3691 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:19:13.294023  3693 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:19:13.294739  3681 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.294867  3681 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:19:13.294924  3681 hybrid_clock.cc:648] HybridClock initialized: now 1786515553294922 us; error 0 us; skew 500 ppm
I20260812 06:19:13.296777  3681 webserver.cc:533] Webserver started at http://127.3.152.126:34579/ using document root <none> and password file <none>
I20260812 06:19:13.297355  3681 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.297449  3681 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.297753  3681 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.299468  3681 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/master-0-root/instance:
uuid: "4c325be0f784424c89847fbb43a63f83"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-7kzw"
I20260812 06:19:13.303181  3681 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.001s
I20260812 06:19:13.305510  3700 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:19:13.306658  3681 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.001s
I20260812 06:19:13.306795  3681 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/master-0-root
uuid: "4c325be0f784424c89847fbb43a63f83"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-7kzw"
I20260812 06:19:13.306903  3681 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-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:19:13.329984  3681 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.330679  3681 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:19:13.330870  3681 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.339056  3681 rpc_server.cc:307] RPC server started. Bound to: 127.3.152.126:34317
I20260812 06:19:13.339124  3785 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.152.126:34317 every 8 connection(s)
I20260812 06:19:13.341442  3786 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:19:13.347265  3786 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: Bootstrap starting.
I20260812 06:19:13.349782  3786 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.350782  3786 log.cc:826] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:13.352536  3786 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: No bootstrap required, opened a new log
I20260812 06:19:13.355520  3786 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER }
I20260812 06:19:13.355697  3786 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.355789  3786 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4c325be0f784424c89847fbb43a63f83, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.356420  3786 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [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: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER }
I20260812 06:19:13.356612  3786 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.356702  3786 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.356832  3786 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.357657  3786 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER }
I20260812 06:19:13.358121  3786 leader_election.cc:304] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [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: 4c325be0f784424c89847fbb43a63f83; no voters: 
I20260812 06:19:13.358484  3786 leader_election.cc:290] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.358650  3792 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.358935  3792 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 1 LEADER]: Becoming Leader. State: Replica: 4c325be0f784424c89847fbb43a63f83, State: Running, Role: LEADER
I20260812 06:19:13.359354  3792 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [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: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER }
I20260812 06:19:13.359668  3786 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:13.361330  3795 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4c325be0f784424c89847fbb43a63f83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER } }
I20260812 06:19:13.361465  3795 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.361706  3796 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4c325be0f784424c89847fbb43a63f83. Latest consensus state: current_term: 1 leader_uuid: "4c325be0f784424c89847fbb43a63f83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4c325be0f784424c89847fbb43a63f83" member_type: VOTER } }
I20260812 06:19:13.361794  3796 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:13.362179  3681 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:13.364627  3815 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:13.364722  3815 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:13.364796  3808 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:13.365584  3808 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:13.370452  3808 catalog_manager.cc:1383] Generated new cluster ID: 94b9fa9232da4b7e85387ac47a603950
I20260812 06:19:13.370548  3808 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:13.380802  3808 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:13.381898  3808 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:13.396898  3808 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: Generated new TSK 0
I20260812 06:19:13.397686  3808 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:13.427595  3681 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:13.430413  3821 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:19:13.430452  3823 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:13.430452  3820 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:19:13.431097  3681 server_base.cc:1061] running on GCE node
I20260812 06:19:13.431284  3681 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:13.431334  3681 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:19:13.431352  3681 hybrid_clock.cc:648] HybridClock initialized: now 1786515553431352 us; error 0 us; skew 500 ppm
I20260812 06:19:13.432355  3681 webserver.cc:533] Webserver started at http://127.3.152.65:38929/ using document root <none> and password file <none>
I20260812 06:19:13.432554  3681 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:13.432602  3681 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:13.432703  3681 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:13.433117  3681 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/instance:
uuid: "15260ec34cf049ddbb25194fe8580c37"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-7kzw"
I20260812 06:19:13.434834  3681 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:13.435902  3829 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:19:13.436177  3681 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:13.436254  3681 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root
uuid: "15260ec34cf049ddbb25194fe8580c37"
format_stamp: "Formatted at 2026-08-12 06:19:13 on dist-test-slave-7kzw"
I20260812 06:19:13.436350  3681 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-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:19:13.444141  3681 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:13.444566  3681 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:13.445071  3681 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:13.445964  3681 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:13.446019  3681 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.446085  3681 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:13.446128  3681 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:13.453120  3681 rpc_server.cc:307] RPC server started. Bound to: 127.3.152.65:35919
I20260812 06:19:13.453154  3916 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.152.65:35919 every 8 connection(s)
I20260812 06:19:13.466591  3917 heartbeater.cc:344] Connected to a master server at 127.3.152.126:34317
I20260812 06:19:13.466892  3917 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:13.467422  3917 heartbeater.cc:507] Master 127.3.152.126:34317 requested a full tablet report, sending...
I20260812 06:19:13.468842  3715 ts_manager.cc:194] Registered new tserver with Master: 15260ec34cf049ddbb25194fe8580c37 (127.3.152.65:35919)
I20260812 06:19:13.469470  3681 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015665289s
I20260812 06:19:13.470237  3715 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:47928
I20260812 06:19:13.479187  3715 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:47944:
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:19:13.492986  3872 tablet_service.cc:1511] Processing CreateTablet for tablet 11abdf0f0b3d4bc780061996b0b38d90 (DEFAULT_TABLE table=heavy-update-compaction-test [id=41a5f8674b824015ad9c6afa2b167bc8]), partition=
I20260812 06:19:13.493455  3872 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 11abdf0f0b3d4bc780061996b0b38d90. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:13.495754  3935 tablet_bootstrap.cc:492] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Bootstrap starting.
I20260812 06:19:13.497396  3935 tablet_bootstrap.cc:654] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:13.498572  3935 tablet_bootstrap.cc:492] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: No bootstrap required, opened a new log
I20260812 06:19:13.498697  3935 ts_tablet_manager.cc:1403] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:13.499137  3935 raft_consensus.cc:359] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15260ec34cf049ddbb25194fe8580c37" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 35919 } }
I20260812 06:19:13.499270  3935 raft_consensus.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:13.499320  3935 raft_consensus.cc:740] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 15260ec34cf049ddbb25194fe8580c37, State: Initialized, Role: FOLLOWER
I20260812 06:19:13.499509  3935 consensus_queue.cc:260] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [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: "15260ec34cf049ddbb25194fe8580c37" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 35919 } }
I20260812 06:19:13.499630  3935 raft_consensus.cc:399] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:13.499681  3935 raft_consensus.cc:493] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:13.499738  3935 raft_consensus.cc:3060] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:13.500823  3935 raft_consensus.cc:515] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15260ec34cf049ddbb25194fe8580c37" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 35919 } }
I20260812 06:19:13.501015  3935 leader_election.cc:304] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [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: 15260ec34cf049ddbb25194fe8580c37; no voters: 
I20260812 06:19:13.501257  3935 leader_election.cc:290] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:13.501591  3935 ts_tablet_manager.cc:1434] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:13.501619  3939 raft_consensus.cc:2804] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:13.502020  3917 heartbeater.cc:499] Master 127.3.152.126:34317 was elected leader, sending a full tablet report...
I20260812 06:19:13.501856  3939 raft_consensus.cc:697] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 1 LEADER]: Becoming Leader. State: Replica: 15260ec34cf049ddbb25194fe8580c37, State: Running, Role: LEADER
I20260812 06:19:13.502521  3939 consensus_queue.cc:237] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [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: "15260ec34cf049ddbb25194fe8580c37" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 35919 } }
I20260812 06:19:13.505508  3715 catalog_manager.cc:5719] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 reported cstate change: term changed from 0 to 1, leader changed from <none> to 15260ec34cf049ddbb25194fe8580c37 (127.3.152.65). New cstate: current_term: 1 leader_uuid: "15260ec34cf049ddbb25194fe8580c37" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "15260ec34cf049ddbb25194fe8580c37" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 35919 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:13.572873  3681 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.058s	user 0.017s	sys 0.010s
I20260812 06:19:13.704272  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=19.054940
I20260812 06:19:13.859890  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.155s	user 0.125s	sys 0.028s Metrics: {"bytes_written":9066585,"cfile_init":1,"compiler_manager_pool.queue_time_us":253,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":986,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37348,"lbm_writes_lt_1ms":678,"mutex_wait_us":203,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":161024,"thread_start_us":131,"threads_started":1,"update_count":1105}
I20260812 06:19:13.861073  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling LogGCOp(11abdf0f0b3d4bc780061996b0b38d90): free 20743880 bytes of WAL
I20260812 06:19:13.861368  3835 log_reader.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90: removed 2 log segments from log reader
I20260812 06:19:13.861444  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000001 (ops 1-6)
I20260812 06:19:13.861515  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000002 (ops 7-11)
I20260812 06:19:13.865932  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: LogGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:13.866286  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:13.881439  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.015s	user 0.003s	sys 0.008s Metrics: {"bytes_written":3241130,"delete_count":0,"lbm_write_time_us":4540,"lbm_writes_lt_1ms":82,"reinsert_count":0,"update_count":395}
I20260812 06:19:13.881911  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.007988  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.126s	user 0.087s	sys 0.023s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569843,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":620,"lbm_read_time_us":6144,"lbm_reads_lt_1ms":368,"lbm_write_time_us":24744,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":9600,"thread_start_us":275,"threads_started":5,"update_count":1500}
I20260812 06:19:14.008668  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90): 16411392 bytes on disk
I20260812 06:19:14.009254  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:14.009766  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:14.055429  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.046s	user 0.012s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15934,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.055858  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:14.066530  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4080,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.066993  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.187392  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.120s	user 0.089s	sys 0.028s 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":1167,"lbm_read_time_us":9533,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21797,"lbm_writes_lt_1ms":443,"mutex_wait_us":338,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:19:14.187885  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:14.244004  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.056s	user 0.027s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17269,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.244613  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:14.255928  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4410,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.256481  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.408228  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.152s	user 0.115s	sys 0.031s 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":213,"lbm_read_time_us":11103,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23816,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.408897  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:14.452392  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.043s	user 0.021s	sys 0.017s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17394,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.452970  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.561062  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.108s	user 0.087s	sys 0.020s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569749,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1462,"lbm_read_time_us":7407,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19266,"lbm_writes_lt_1ms":343,"mutex_wait_us":78,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":12160,"update_count":1500}
I20260812 06:19:14.561632  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:14.611883  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.050s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18301,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.612334  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:14.626235  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5147,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.626864  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.772205  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.145s	user 0.121s	sys 0.021s 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":305,"lbm_read_time_us":10857,"lbm_reads_lt_1ms":472,"lbm_write_time_us":30045,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:14.772827  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:14.824949  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.052s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14671,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.825455  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:14.835958  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:14.836354  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:14.984926  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.148s	user 0.117s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":11578,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24003,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:19:14.985576  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:15.027272  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.042s	user 0.034s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17934,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.027956  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:15.131884  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.104s	user 0.075s	sys 0.028s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":197,"lbm_read_time_us":6529,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19087,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":1500}
I20260812 06:19:15.132541  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=10.126437
I20260812 06:19:15.170804  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.038s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16140,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:15.171361  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:15.224812  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.053s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1394,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2359,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:15.225632  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling LogGCOp(11abdf0f0b3d4bc780061996b0b38d90): free 112239262 bytes of WAL
I20260812 06:19:15.225850  3835 log_reader.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90: removed 11 log segments from log reader
I20260812 06:19:15.225898  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000003 (ops 12-16)
I20260812 06:19:15.225926  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000004 (ops 17-21)
I20260812 06:19:15.225984  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000005 (ops 22-26)
I20260812 06:19:15.226012  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000006 (ops 27-31)
I20260812 06:19:15.226050  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000007 (ops 32-36)
I20260812 06:19:15.226100  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000008 (ops 37-40)
I20260812 06:19:15.226140  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000009 (ops 41-45)
I20260812 06:19:15.226173  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000010 (ops 46-50)
I20260812 06:19:15.226212  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000011 (ops 51-55)
I20260812 06:19:15.226248  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000012 (ops 56-60)
I20260812 06:19:15.226289  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000013 (ops 61-65)
I20260812 06:19:15.249825  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: LogGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.024s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:15.250336  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=6.157687
I20260812 06:19:15.272804  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.022s	user 0.011s	sys 0.009s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9467,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:15.273273  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling LogGCOp(11abdf0f0b3d4bc780061996b0b38d90): free 12017983 bytes of WAL
I20260812 06:19:15.273531  3835 log_reader.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90: removed 1 log segments from log reader
I20260812 06:19:15.273581  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000014 (ops 66-70)
I20260812 06:19:15.276285  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: LogGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:15.276723  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90): 462 bytes on disk
I20260812 06:19:15.277690  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:15.278242  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:15.293308  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.293759  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:15.459434  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.166s	user 0.114s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":711,"lbm_read_time_us":10774,"lbm_reads_lt_1ms":665,"lbm_write_time_us":35563,"lbm_writes_lt_1ms":643,"mutex_wait_us":24,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:19:15.460070  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:15.507258  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.047s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20726,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.507764  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:15.524427  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.524994  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:15.696682  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.171s	user 0.119s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":838,"lbm_read_time_us":11262,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32055,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18688,"update_count":2500}
I20260812 06:19:15.697337  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:15.754071  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.057s	user 0.026s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23631,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.754617  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:15.907891  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.153s	user 0.105s	sys 0.039s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":921,"lbm_read_time_us":11070,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22516,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.908510  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:15.960448  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.052s	user 0.023s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18718,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:15.960949  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:15.972524  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4197,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:15.973008  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:16.154667  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.181s	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":2815,"lbm_read_time_us":11135,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29022,"lbm_writes_lt_1ms":543,"mutex_wait_us":2167,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:19:16.155395  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:16.202426  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.047s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21282,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.202934  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:16.214828  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4615,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.215304  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:16.382869  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.167s	user 0.108s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":11070,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31335,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:16.383386  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:16.439260  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.056s	user 0.036s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":27634,"lbm_writes_1-10_ms":4,"lbm_writes_lt_1ms":399,"reinsert_count":0,"update_count":2000}
I20260812 06:19:16.439728  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:16.449949  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3890,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.450534  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:16.605585  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.155s	user 0.101s	sys 0.049s 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":910,"lbm_read_time_us":12365,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30834,"lbm_writes_lt_1ms":543,"mutex_wait_us":250,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:16.606303  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=11.118625
I20260812 06:19:16.639243  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.032s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14033,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:16.640043  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:16.669217  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.029s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6581,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:16.669790  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:16.680405  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:16.680967  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:16.712538  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":1287,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1715,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:16.713377  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling LogGCOp(11abdf0f0b3d4bc780061996b0b38d90): free 121006384 bytes of WAL
I20260812 06:19:16.713660  3835 log_reader.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90: removed 12 log segments from log reader
I20260812 06:19:16.713721  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000015 (ops 71-75)
I20260812 06:19:16.713759  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000016 (ops 76-80)
I20260812 06:19:16.713795  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000017 (ops 81-85)
I20260812 06:19:16.713825  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000018 (ops 86-90)
I20260812 06:19:16.713855  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000019 (ops 91-95)
I20260812 06:19:16.713877  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000020 (ops 96-100)
I20260812 06:19:16.713907  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000021 (ops 101-105)
I20260812 06:19:16.713940  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000022 (ops 106-110)
I20260812 06:19:16.713974  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000023 (ops 111-115)
I20260812 06:19:16.714002  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000024 (ops 116-120)
I20260812 06:19:16.714030  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000025 (ops 121-124)
I20260812 06:19:16.714059  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000026 (ops 125-129)
I20260812 06:19:16.745536  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: LogGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:16.745962  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90): 483 bytes on disk
I20260812 06:19:16.746582  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:16.747149  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=3.181125
I20260812 06:19:16.760035  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":4532,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:16.760556  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:16.770646  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:16.771265  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:17.013360  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.242s	user 0.159s	sys 0.069s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1037,"lbm_read_time_us":15840,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40101,"lbm_writes_lt_1ms":743,"mutex_wait_us":325,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":67,"threads_started":1,"update_count":3500}
I20260812 06:19:17.013895  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=15.087375
I20260812 06:19:17.072785  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.059s	user 0.028s	sys 0.028s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":22157,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:17.073463  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=3.181125
I20260812 06:19:17.087002  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.013s	user 0.005s	sys 0.008s Metrics: {"bytes_written":5128262,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:19:17.087431  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.196750
I20260812 06:19:17.095065  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.007s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":2790,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:19:17.095443  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:17.294482  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.199s	user 0.128s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":229,"lbm_read_time_us":13944,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34774,"lbm_writes_lt_1ms":643,"mutex_wait_us":22,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":3000}
I20260812 06:19:17.295195  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:17.342809  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.047s	user 0.032s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20693,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.343360  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:17.489120  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.146s	user 0.095s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1132,"lbm_read_time_us":10073,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24378,"lbm_writes_lt_1ms":443,"mutex_wait_us":556,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.490221  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=11.118625
I20260812 06:19:17.531653  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.041s	user 0.025s	sys 0.015s Metrics: {"bytes_written":13168994,"delete_count":0,"lbm_write_time_us":18277,"lbm_writes_lt_1ms":324,"reinsert_count":0,"update_count":1605}
I20260812 06:19:17.532109  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:17.553225  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.021s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3651384,"delete_count":0,"lbm_write_time_us":4096,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:19:17.553776  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:17.564756  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4027,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:17.565611  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:17.758141  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.192s	user 0.121s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774783,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":211,"lbm_read_time_us":13315,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29517,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:17.758828  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:17.811084  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.052s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:17.811651  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:17.821990  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4130,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:17.822458  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:17.992836  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.170s	user 0.123s	sys 0.036s 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":207,"lbm_read_time_us":11093,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33463,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:19:17.993607  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:18.042843  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.049s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20918,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.043393  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:18.056754  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4542,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.057451  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:18.231546  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.174s	user 0.144s	sys 0.026s 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":148,"lbm_read_time_us":12554,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35020,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:18.232391  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=14.095187
I20260812 06:19:18.279948  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.047s	user 0.027s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18471,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:18.280521  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:18.295879  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.015s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:18.296360  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:18.329327  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushMRSOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.033s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1150,"drs_written":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2095,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:18.330029  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling LogGCOp(11abdf0f0b3d4bc780061996b0b38d90): free 132571663 bytes of WAL
I20260812 06:19:18.330296  3835 log_reader.cc:385] T 11abdf0f0b3d4bc780061996b0b38d90: removed 13 log segments from log reader
I20260812 06:19:18.330359  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000027 (ops 130-134)
I20260812 06:19:18.330399  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000028 (ops 135-139)
I20260812 06:19:18.330430  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000029 (ops 140-144)
I20260812 06:19:18.330451  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000030 (ops 145-149)
I20260812 06:19:18.330520  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000031 (ops 150-154)
I20260812 06:19:18.330546  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000032 (ops 155-159)
I20260812 06:19:18.330576  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000033 (ops 160-164)
I20260812 06:19:18.330602  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000034 (ops 165-168)
I20260812 06:19:18.330631  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000035 (ops 169-173)
I20260812 06:19:18.330662  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000036 (ops 174-178)
I20260812 06:19:18.330695  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000037 (ops 179-182)
I20260812 06:19:18.330727  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000038 (ops 183-187)
I20260812 06:19:18.330765  3835 log.cc:1079] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/11abdf0f0b3d4bc780061996b0b38d90/wal-000000039 (ops 188-192)
I20260812 06:19:18.362457  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: LogGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:18.362993  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=3.181125
I20260812 06:19:18.375313  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4592,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:18.375790  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=2.188937
I20260812 06:19:18.389161  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: FlushDeltaMemStoresOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5364,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:18.389725  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90): 492 bytes on disk
I20260812 06:19:18.390306  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: UndoDeltaBlockGCOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:18.390972  3919 maintenance_manager.cc:419] P 15260ec34cf049ddbb25194fe8580c37: Scheduling MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90): perf score=1.000000
I20260812 06:19:18.493170  3681 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.920s	user 1.912s	sys 0.084s
I20260812 06:19:18.599409  3681 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.106s	user 0.004s	sys 0.000s
I20260812 06:19:18.600201  3681 tablet_server.cc:179] TabletServer@127.3.152.65:0 shutting down...
I20260812 06:19:18.629146  3835 maintenance_manager.cc:643] P 15260ec34cf049ddbb25194fe8580c37: MajorDeltaCompactionOp(11abdf0f0b3d4bc780061996b0b38d90) complete. Timing: real 0.238s	user 0.132s	sys 0.100s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1181,"lbm_read_time_us":15494,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36846,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19840,"thread_start_us":90,"threads_started":1,"update_count":3500}
I20260812 06:19:18.630100  3681 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:18.630599  3681 tablet_replica.cc:333] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37: stopping tablet replica
I20260812 06:19:18.630872  3681 raft_consensus.cc:2243] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.631131  3681 raft_consensus.cc:2272] T 11abdf0f0b3d4bc780061996b0b38d90 P 15260ec34cf049ddbb25194fe8580c37 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.648955  3681 tablet_server.cc:196] TabletServer@127.3.152.65:0 shutdown complete.
I20260812 06:19:18.691641  3681 master.cc:562] Master@127.3.152.126:34317 shutting down...
I20260812 06:19:18.696044  3681 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:18.696285  3681 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:18.696384  3681 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4c325be0f784424c89847fbb43a63f83: stopping tablet replica
I20260812 06:19:18.709318  3681 master.cc:584] Master@127.3.152.126:34317 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5523 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:18.826320  3681 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.152.126:39707
I20260812 06:19:18.826926  3681 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:18.830802  3681 server_base.cc:1061] running on GCE node
W20260812 06:19:18.830856  3969 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:18.830991  3966 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:19:18.830860  3965 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:19:18.831315  3681 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.831369  3681 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:19:18.831388  3681 hybrid_clock.cc:648] HybridClock initialized: now 1786515558831388 us; error 0 us; skew 500 ppm
I20260812 06:19:18.832569  3681 webserver.cc:533] Webserver started at http://127.3.152.126:41687/ using document root <none> and password file <none>
I20260812 06:19:18.832731  3681 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.832784  3681 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.832852  3681 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.833253  3681 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/master-0-root/instance:
uuid: "8784801a0a8449b28190a8f313a91310"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-7kzw"
I20260812 06:19:18.835139  3681 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:18.836352  3977 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:19:18.836767  3681 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:18.836889  3681 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/master-0-root
uuid: "8784801a0a8449b28190a8f313a91310"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-7kzw"
I20260812 06:19:18.836987  3681 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-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:19:18.845108  3681 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.845580  3681 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.851266  3681 rpc_server.cc:307] RPC server started. Bound to: 127.3.152.126:39707
I20260812 06:19:18.857870  4052 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.152.126:39707 every 8 connection(s)
I20260812 06:19:18.857966  4053 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:19:18.859989  4053 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310: Bootstrap starting.
I20260812 06:19:18.860844  4053 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.862074  4053 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310: No bootstrap required, opened a new log
I20260812 06:19:18.862521  4053 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8784801a0a8449b28190a8f313a91310" member_type: VOTER }
I20260812 06:19:18.862639  4053 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.862665  4053 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8784801a0a8449b28190a8f313a91310, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.862838  4053 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [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: "8784801a0a8449b28190a8f313a91310" member_type: VOTER }
I20260812 06:19:18.862939  4053 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.862967  4053 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.863000  4053 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.863747  4053 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8784801a0a8449b28190a8f313a91310" member_type: VOTER }
I20260812 06:19:18.863875  4053 leader_election.cc:304] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [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: 8784801a0a8449b28190a8f313a91310; no voters: 
I20260812 06:19:18.864092  4053 leader_election.cc:290] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.864207  4057 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.864410  4057 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 1 LEADER]: Becoming Leader. State: Replica: 8784801a0a8449b28190a8f313a91310, State: Running, Role: LEADER
I20260812 06:19:18.864681  4053 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:18.864634  4057 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [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: "8784801a0a8449b28190a8f313a91310" member_type: VOTER }
I20260812 06:19:18.865242  4059 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8784801a0a8449b28190a8f313a91310. Latest consensus state: current_term: 1 leader_uuid: "8784801a0a8449b28190a8f313a91310" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8784801a0a8449b28190a8f313a91310" member_type: VOTER } }
I20260812 06:19:18.865303  4058 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8784801a0a8449b28190a8f313a91310" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8784801a0a8449b28190a8f313a91310" member_type: VOTER } }
I20260812 06:19:18.865415  4059 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.865504  4058 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:18.866034  4064 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:18.867169  4064 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:18.867406  3681 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:18.869496  4064 catalog_manager.cc:1383] Generated new cluster ID: 89a86042b5b347b097626a5566b2290a
I20260812 06:19:18.869567  4064 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:18.881803  4064 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:18.882548  4064 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:18.891902  4064 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310: Generated new TSK 0
I20260812 06:19:18.892118  4064 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:18.900079  3681 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:18.902663  4084 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:18.902822  3681 server_base.cc:1061] running on GCE node
W20260812 06:19:18.902663  4080 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:19:18.902901  4087 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:19:18.903182  3681 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:18.903249  3681 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:19:18.903275  3681 hybrid_clock.cc:648] HybridClock initialized: now 1786515558903275 us; error 0 us; skew 500 ppm
I20260812 06:19:18.904189  3681 webserver.cc:533] Webserver started at http://127.3.152.65:42013/ using document root <none> and password file <none>
I20260812 06:19:18.904407  3681 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:18.904484  3681 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:18.904563  3681 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:18.905021  3681 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/instance:
uuid: "0b4be2c1a4724687b7e91a7bcd8656cf"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-7kzw"
I20260812 06:19:18.906853  3681 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:18.908170  4093 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:19:18.908576  3681 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:18.908708  3681 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root
uuid: "0b4be2c1a4724687b7e91a7bcd8656cf"
format_stamp: "Formatted at 2026-08-12 06:19:18 on dist-test-slave-7kzw"
I20260812 06:19:18.908806  3681 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-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:19:18.932804  3681 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:18.933295  3681 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:18.933668  3681 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:18.934190  3681 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:18.934252  3681 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.934316  3681 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:18.934360  3681 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:18.939214  3681 rpc_server.cc:307] RPC server started. Bound to: 127.3.152.65:37903
I20260812 06:19:18.940912  4190 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.152.65:37903 every 8 connection(s)
I20260812 06:19:18.950829  4191 heartbeater.cc:344] Connected to a master server at 127.3.152.126:39707
I20260812 06:19:18.951036  4191 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:18.951335  4191 heartbeater.cc:507] Master 127.3.152.126:39707 requested a full tablet report, sending...
I20260812 06:19:18.952327  4003 ts_manager.cc:194] Registered new tserver with Master: 0b4be2c1a4724687b7e91a7bcd8656cf (127.3.152.65:37903)
I20260812 06:19:18.952646  3681 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012487694s
I20260812 06:19:18.953459  4003 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42252
I20260812 06:19:18.961265  4003 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42266:
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:19:18.971897  4141 tablet_service.cc:1511] Processing CreateTablet for tablet 570620facadf47068557bb83651825a4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=22dc0668e9624b86b4c3419b10422331]), partition=
I20260812 06:19:18.972179  4141 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 570620facadf47068557bb83651825a4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:18.974527  4207 tablet_bootstrap.cc:492] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Bootstrap starting.
I20260812 06:19:18.975504  4207 tablet_bootstrap.cc:654] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:18.976866  4207 tablet_bootstrap.cc:492] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: No bootstrap required, opened a new log
I20260812 06:19:18.976949  4207 ts_tablet_manager.cc:1403] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:18.977473  4207 raft_consensus.cc:359] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b4be2c1a4724687b7e91a7bcd8656cf" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 37903 } }
I20260812 06:19:18.977573  4207 raft_consensus.cc:385] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:18.977597  4207 raft_consensus.cc:740] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0b4be2c1a4724687b7e91a7bcd8656cf, State: Initialized, Role: FOLLOWER
I20260812 06:19:18.977737  4207 consensus_queue.cc:260] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [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: "0b4be2c1a4724687b7e91a7bcd8656cf" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 37903 } }
I20260812 06:19:18.977859  4207 raft_consensus.cc:399] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:18.977922  4207 raft_consensus.cc:493] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:18.977969  4207 raft_consensus.cc:3060] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:18.981093  4207 raft_consensus.cc:515] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b4be2c1a4724687b7e91a7bcd8656cf" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 37903 } }
I20260812 06:19:18.981273  4207 leader_election.cc:304] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [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: 0b4be2c1a4724687b7e91a7bcd8656cf; no voters: 
I20260812 06:19:18.981554  4207 leader_election.cc:290] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:18.981648  4209 raft_consensus.cc:2804] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:18.981817  4209 raft_consensus.cc:697] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 1 LEADER]: Becoming Leader. State: Replica: 0b4be2c1a4724687b7e91a7bcd8656cf, State: Running, Role: LEADER
I20260812 06:19:18.981989  4207 ts_tablet_manager.cc:1434] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Time spent starting tablet: real 0.005s	user 0.003s	sys 0.000s
I20260812 06:19:18.981959  4209 consensus_queue.cc:237] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [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: "0b4be2c1a4724687b7e91a7bcd8656cf" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 37903 } }
I20260812 06:19:18.982053  4191 heartbeater.cc:499] Master 127.3.152.126:39707 was elected leader, sending a full tablet report...
I20260812 06:19:18.983484  4003 catalog_manager.cc:5719] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf reported cstate change: term changed from 0 to 1, leader changed from <none> to 0b4be2c1a4724687b7e91a7bcd8656cf (127.3.152.65). New cstate: current_term: 1 leader_uuid: "0b4be2c1a4724687b7e91a7bcd8656cf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0b4be2c1a4724687b7e91a7bcd8656cf" member_type: VOTER last_known_addr { host: "127.3.152.65" port: 37903 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:19.045181  3681 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.016s	sys 0.008s
I20260812 06:19:19.191407  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushMRSOp(570620facadf47068557bb83651825a4): perf score=19.054940
I20260812 06:19:19.335384  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushMRSOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.144s	user 0.079s	sys 0.063s Metrics: {"bytes_written":8984539,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":235,"dirs.run_wall_time_us":931,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34458,"lbm_writes_lt_1ms":676,"mutex_wait_us":836,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1095}
I20260812 06:19:19.336393  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling LogGCOp(570620facadf47068557bb83651825a4): free 20743880 bytes of WAL
I20260812 06:19:19.336695  4100 log_reader.cc:385] T 570620facadf47068557bb83651825a4: removed 2 log segments from log reader
I20260812 06:19:19.336781  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000001 (ops 1-6)
I20260812 06:19:19.336846  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000002 (ops 7-11)
I20260812 06:19:19.342406  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: LogGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:19.342911  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4): 16411392 bytes on disk
I20260812 06:19:19.343467  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:19.344043  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:19.366663  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.022s	user 0.002s	sys 0.009s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4268,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:19:19.367142  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:19.377507  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3852,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:19.377977  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:19.552521  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.174s	user 0.111s	sys 0.063s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672378,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":482,"lbm_read_time_us":13796,"lbm_reads_lt_1ms":469,"lbm_write_time_us":27135,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":359,"threads_started":5,"update_count":2000}
I20260812 06:19:19.553229  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=11.118625
I20260812 06:19:19.588184  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.035s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12635686,"delete_count":0,"lbm_write_time_us":15295,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1540}
I20260812 06:19:19.588668  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:19.602231  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.013s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":4701,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:19.602996  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:19.753595  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.150s	user 0.112s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":361,"lbm_read_time_us":8274,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26868,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:19:19.754274  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:19.793387  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.039s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17314,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.793862  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:19.804802  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3971,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:19.805442  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:19.936430  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.131s	user 0.088s	sys 0.042s 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":570,"lbm_read_time_us":7946,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25707,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:19.937013  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:19.983868  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.047s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:19.984383  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:19.995952  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.011s	user 0.006s	sys 0.004s 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:19:19.996862  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:20.127097  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.130s	user 0.122s	sys 0.007s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":9898,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24453,"lbm_writes_lt_1ms":443,"mutex_wait_us":63,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:20.127633  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:20.179318  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.052s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14877,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.179857  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.192750  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.193259  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:20.342937  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.150s	user 0.117s	sys 0.032s 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":1071,"lbm_read_time_us":11294,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23591,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:19:20.343566  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:20.386862  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.043s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15820,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.387393  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.402915  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5797,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.403510  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:20.531894  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":712,"lbm_read_time_us":10591,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22519,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19072,"update_count":2000}
I20260812 06:19:20.532539  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:20.578972  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.046s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17341,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:20.579493  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.590095  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.590816  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushMRSOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:20.621232  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushMRSOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.030s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":248,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":76,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:20.621994  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling LogGCOp(570620facadf47068557bb83651825a4): free 112239317 bytes of WAL
I20260812 06:19:20.622262  4100 log_reader.cc:385] T 570620facadf47068557bb83651825a4: removed 11 log segments from log reader
I20260812 06:19:20.622324  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000003 (ops 12-16)
I20260812 06:19:20.622360  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000004 (ops 17-21)
I20260812 06:19:20.622392  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000005 (ops 22-26)
I20260812 06:19:20.622427  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000006 (ops 27-30)
I20260812 06:19:20.622458  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000007 (ops 31-35)
I20260812 06:19:20.622509  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000008 (ops 36-40)
I20260812 06:19:20.622536  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000009 (ops 41-45)
I20260812 06:19:20.622573  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000010 (ops 46-50)
I20260812 06:19:20.622612  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000011 (ops 51-55)
I20260812 06:19:20.622637  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000012 (ops 56-60)
I20260812 06:19:20.622658  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000013 (ops 61-65)
I20260812 06:19:20.652398  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: LogGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.030s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:20.652904  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.678524  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.025s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6333,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.678990  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4): 447 bytes on disk
I20260812 06:19:20.679399  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4) 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:19:20.679837  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.690840  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.691311  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:20.874795  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.183s	user 0.137s	sys 0.046s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":846,"lbm_read_time_us":12999,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39049,"lbm_writes_lt_1ms":643,"mutex_wait_us":49,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":113,"threads_started":1,"update_count":3000}
I20260812 06:19:20.875527  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=14.095187
I20260812 06:19:20.927042  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.051s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20173,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:20.927676  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:20.943348  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5821,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:20.943992  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:21.094763  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.151s	user 0.115s	sys 0.033s 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":675,"lbm_read_time_us":10046,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30112,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:21.095405  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=11.118625
I20260812 06:19:21.134529  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.039s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16435,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:21.135087  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.152696  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.017s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.153216  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.162699  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.009s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3678,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.163096  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:21.317569  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.154s	user 0.102s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1343,"lbm_read_time_us":9848,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30977,"lbm_writes_lt_1ms":543,"mutex_wait_us":301,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2500}
I20260812 06:19:21.318207  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=11.118625
I20260812 06:19:21.348163  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.030s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12962,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:21.348938  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.363565  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5232,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:21.364274  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:21.500348  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.136s	user 0.103s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":144,"lbm_read_time_us":10942,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26415,"lbm_writes_lt_1ms":443,"mutex_wait_us":44,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:21.501044  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:21.553807  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.053s	user 0.021s	sys 0.022s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15865,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.554348  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.572636  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.573287  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:21.743507  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.170s	user 0.105s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":335,"lbm_read_time_us":14316,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27321,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:19:21.744280  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:21.788471  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.044s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15743,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.789013  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.800693  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:21.801383  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:21.925068  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.123s	user 0.108s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":593,"lbm_read_time_us":9535,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22560,"lbm_writes_lt_1ms":443,"mutex_wait_us":251,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":37888,"update_count":2000}
I20260812 06:19:21.925818  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:21.967653  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.042s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15918,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:21.968218  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:21.980453  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.012s	user 0.010s	sys 0.000s 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:19:21.981032  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushMRSOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:22.009394  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushMRSOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1190,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1490,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:22.010205  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling LogGCOp(570620facadf47068557bb83651825a4): free 112239265 bytes of WAL
I20260812 06:19:22.010490  4100 log_reader.cc:385] T 570620facadf47068557bb83651825a4: removed 11 log segments from log reader
I20260812 06:19:22.010552  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000014 (ops 66-70)
I20260812 06:19:22.010591  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000015 (ops 71-75)
I20260812 06:19:22.010623  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000016 (ops 76-80)
I20260812 06:19:22.010660  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000017 (ops 81-85)
I20260812 06:19:22.010692  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000018 (ops 86-90)
I20260812 06:19:22.010730  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000019 (ops 91-95)
I20260812 06:19:22.010756  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000020 (ops 96-100)
I20260812 06:19:22.010782  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000021 (ops 101-104)
I20260812 06:19:22.010815  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000022 (ops 105-109)
I20260812 06:19:22.010847  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000023 (ops 110-114)
I20260812 06:19:22.010874  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000024 (ops 115-119)
I20260812 06:19:22.039021  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: LogGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:19:22.039498  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:22.063849  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.024s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.064301  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling LogGCOp(570620facadf47068557bb83651825a4): free 12017983 bytes of WAL
I20260812 06:19:22.064512  4100 log_reader.cc:385] T 570620facadf47068557bb83651825a4: removed 1 log segments from log reader
I20260812 06:19:22.064571  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000025 (ops 120-124)
I20260812 06:19:22.067545  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: LogGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:22.067912  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:22.080581  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.081063  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4): 447 bytes on disk
I20260812 06:19:22.081640  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:22.082254  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:22.271517  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.189s	user 0.129s	sys 0.060s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1008,"lbm_read_time_us":16030,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36015,"lbm_writes_lt_1ms":643,"mutex_wait_us":111,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:22.272226  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=14.095187
I20260812 06:19:22.326965  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.052s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23584,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.327862  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:22.341076  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.013s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.341601  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:22.489907  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.148s	user 0.116s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":10731,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29764,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:19:22.490417  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=14.095187
I20260812 06:19:22.544447  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.054s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.544986  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:22.556754  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.557253  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:22.706625  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.149s	user 0.110s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":689,"lbm_read_time_us":10495,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28825,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2500}
I20260812 06:19:22.707440  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=14.095187
I20260812 06:19:22.766911  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.059s	user 0.035s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25713,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:22.767469  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:22.781172  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5105,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:22.781757  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:22.961894  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.180s	user 0.132s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":801,"lbm_read_time_us":12417,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32657,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:19:22.962674  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=14.095187
I20260812 06:19:23.023043  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.060s	user 0.025s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22896,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:23.023614  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:23.036975  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.037518  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:23.245230  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.208s	user 0.148s	sys 0.056s 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":423,"lbm_read_time_us":14946,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35055,"lbm_writes_lt_1ms":543,"mutex_wait_us":87,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:19:23.246048  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=15.087375
I20260812 06:19:23.299346  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.053s	user 0.021s	sys 0.031s Metrics: {"bytes_written":17230386,"delete_count":0,"lbm_write_time_us":23757,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:19:23.299875  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:23.320443  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.020s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3282155,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:23.320963  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:23.332352  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.333281  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushMRSOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:23.365499  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushMRSOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.032s	user 0.020s	sys 0.003s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":254,"dirs.run_wall_time_us":1426,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1665,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:23.366315  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling LogGCOp(570620facadf47068557bb83651825a4): free 112239542 bytes of WAL
I20260812 06:19:23.366590  4100 log_reader.cc:385] T 570620facadf47068557bb83651825a4: removed 11 log segments from log reader
I20260812 06:19:23.366724  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000026 (ops 125-129)
I20260812 06:19:23.366791  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000027 (ops 130-134)
I20260812 06:19:23.366835  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000028 (ops 135-139)
I20260812 06:19:23.366883  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000029 (ops 140-144)
I20260812 06:19:23.366927  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000030 (ops 145-148)
I20260812 06:19:23.366972  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000031 (ops 149-153)
I20260812 06:19:23.367014  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000032 (ops 154-158)
I20260812 06:19:23.367058  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000033 (ops 159-163)
I20260812 06:19:23.367100  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000034 (ops 164-168)
I20260812 06:19:23.367141  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000035 (ops 169-173)
I20260812 06:19:23.367188  4100 log.cc:1079] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: Deleting log segment in path: /tmp/dist-test-taskjX1Pks/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515553274551-3681-0/minicluster-data/ts-0-root/wals/570620facadf47068557bb83651825a4/wal-000000036 (ops 174-178)
I20260812 06:19:23.396872  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: LogGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.030s	user 0.002s	sys 0.024s Metrics: {}
I20260812 06:19:23.397284  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4): 447 bytes on disk
I20260812 06:19:23.397733  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: UndoDeltaBlockGCOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.398294  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=3.181125
I20260812 06:19:23.414126  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.016s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4774,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:23.414746  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:23.429670  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5791,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.430258  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:23.681805  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.251s	user 0.181s	sys 0.068s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082248,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":547,"lbm_read_time_us":19450,"lbm_reads_lt_1ms":875,"lbm_write_time_us":46215,"lbm_writes_lt_1ms":843,"mutex_wait_us":54,"peak_mem_usage":100395616,"reinsert_count":0,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:19:23.682555  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=18.063937
I20260812 06:19:23.738334  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.056s	user 0.038s	sys 0.017s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25167,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:23.739068  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=3.181125
I20260812 06:19:23.766341  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.027s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6423,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:23.766957  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=2.188937
I20260812 06:19:23.777343  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.777808  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling MajorDeltaCompactionOp(570620facadf47068557bb83651825a4): perf score=1.000000
I20260812 06:19:23.907750  3681 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.862s	user 1.844s	sys 0.141s
I20260812 06:19:23.986420  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: MajorDeltaCompactionOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.208s	user 0.180s	sys 0.028s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979620,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":803,"lbm_read_time_us":16261,"lbm_reads_lt_1ms":769,"lbm_write_time_us":46269,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":742,"mutex_wait_us":107,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3500}
I20260812 06:19:23.988024  4192 maintenance_manager.cc:419] P 0b4be2c1a4724687b7e91a7bcd8656cf: Scheduling FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4): perf score=10.126437
I20260812 06:19:23.995126  3681 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.005s	sys 0.000s
I20260812 06:19:23.995666  3681 tablet_server.cc:179] TabletServer@127.3.152.65:0 shutting down...
I20260812 06:19:24.024554  4100 maintenance_manager.cc:643] P 0b4be2c1a4724687b7e91a7bcd8656cf: FlushDeltaMemStoresOp(570620facadf47068557bb83651825a4) complete. Timing: real 0.036s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15813,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:24.025254  3681 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:24.025599  3681 tablet_replica.cc:333] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf: stopping tablet replica
I20260812 06:19:24.025791  3681 raft_consensus.cc:2243] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.025954  3681 raft_consensus.cc:2272] T 570620facadf47068557bb83651825a4 P 0b4be2c1a4724687b7e91a7bcd8656cf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.031267  3681 tablet_server.cc:196] TabletServer@127.3.152.65:0 shutdown complete.
I20260812 06:19:24.045706  3681 master.cc:562] Master@127.3.152.126:39707 shutting down...
I20260812 06:19:24.049861  3681 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:24.050033  3681 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:24.050077  3681 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8784801a0a8449b28190a8f313a91310: stopping tablet replica
I20260812 06:19:24.062979  3681 master.cc:584] Master@127.3.152.126:39707 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5348 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10873 ms total)

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