[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:06.142958  4677 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.145.126:37717
I20260812 06:17:06.144084  4677 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:06.144671  4677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:17:06.151640  4677 server_base.cc:1061] running on GCE node
W20260812 06:17:06.151585  4682 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:06.151582  4685 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:06.151988  4683 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:06.152614  4677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:06.152714  4677 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:06.152787  4677 hybrid_clock.cc:648] HybridClock initialized: now 1786515426152785 us; error 0 us; skew 500 ppm
I20260812 06:17:06.154727  4677 webserver.cc:533] Webserver started at http://127.4.145.126:43827/ using document root <none> and password file <none>
I20260812 06:17:06.155308  4677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:06.155400  4677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:06.155727  4677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:06.157482  4677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/master-0-root/instance:
uuid: "b42ce38bc9374892a4defc9f9c1638bc"
format_stamp: "Formatted at 2026-08-12 06:17:06 on dist-test-slave-bxbt"
I20260812 06:17:06.161191  4677 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.004s
I20260812 06:17:06.163349  4690 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:06.164521  4677 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:06.164665  4677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/master-0-root
uuid: "b42ce38bc9374892a4defc9f9c1638bc"
format_stamp: "Formatted at 2026-08-12 06:17:06 on dist-test-slave-bxbt"
I20260812 06:17:06.164783  4677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:06.178249  4677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:06.178977  4677 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:06.179177  4677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:06.187011  4677 rpc_server.cc:307] RPC server started. Bound to: 127.4.145.126:37717
I20260812 06:17:06.187018  4742 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.145.126:37717 every 8 connection(s)
I20260812 06:17:06.189461  4743 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:06.195142  4743 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: Bootstrap starting.
I20260812 06:17:06.197600  4743 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:06.198525  4743 log.cc:826] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:06.200449  4743 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: No bootstrap required, opened a new log
I20260812 06:17:06.203275  4743 raft_consensus.cc:359] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER }
I20260812 06:17:06.203452  4743 raft_consensus.cc:385] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:06.203511  4743 raft_consensus.cc:740] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b42ce38bc9374892a4defc9f9c1638bc, State: Initialized, Role: FOLLOWER
I20260812 06:17:06.204196  4743 consensus_queue.cc:260] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [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: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER }
I20260812 06:17:06.204353  4743 raft_consensus.cc:399] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:06.204403  4743 raft_consensus.cc:493] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:06.204504  4743 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:06.205298  4743 raft_consensus.cc:515] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER }
I20260812 06:17:06.205700  4743 leader_election.cc:304] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [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: b42ce38bc9374892a4defc9f9c1638bc; no voters: 
I20260812 06:17:06.206115  4743 leader_election.cc:290] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:06.206267  4746 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:06.206554  4746 raft_consensus.cc:697] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 1 LEADER]: Becoming Leader. State: Replica: b42ce38bc9374892a4defc9f9c1638bc, State: Running, Role: LEADER
I20260812 06:17:06.206995  4746 consensus_queue.cc:237] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [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: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER }
I20260812 06:17:06.207187  4743 sys_catalog.cc:565] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:06.208871  4747 sys_catalog.cc:455] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b42ce38bc9374892a4defc9f9c1638bc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER } }
I20260812 06:17:06.209002  4747 sys_catalog.cc:458] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:06.209370  4756 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:06.209335  4748 sys_catalog.cc:455] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [sys.catalog]: SysCatalogTable state changed. Reason: New leader b42ce38bc9374892a4defc9f9c1638bc. Latest consensus state: current_term: 1 leader_uuid: "b42ce38bc9374892a4defc9f9c1638bc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b42ce38bc9374892a4defc9f9c1638bc" member_type: VOTER } }
I20260812 06:17:06.209504  4748 sys_catalog.cc:458] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:06.209664  4677 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:06.211814  4756 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:06.216666  4756 catalog_manager.cc:1383] Generated new cluster ID: 345f672ef86e40cc8fc003b105567112
I20260812 06:17:06.216745  4756 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:06.242676  4756 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:06.243609  4756 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:06.252707  4756 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: Generated new TSK 0
I20260812 06:17:06.253402  4756 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:06.274667  4677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:06.277544  4765 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:06.277649  4766 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:06.277680  4677 server_base.cc:1061] running on GCE node
W20260812 06:17:06.277562  4768 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:06.278085  4677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:06.278154  4677 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:06.278189  4677 hybrid_clock.cc:648] HybridClock initialized: now 1786515426278189 us; error 0 us; skew 500 ppm
I20260812 06:17:06.279160  4677 webserver.cc:533] Webserver started at http://127.4.145.65:34453/ using document root <none> and password file <none>
I20260812 06:17:06.279345  4677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:06.279428  4677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:06.279510  4677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:06.280016  4677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/instance:
uuid: "c8c7ebe3994e4e0e947e2cedef35a480"
format_stamp: "Formatted at 2026-08-12 06:17:06 on dist-test-slave-bxbt"
I20260812 06:17:06.281631  4677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:06.282644  4773 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:06.282891  4677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:06.282967  4677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root
uuid: "c8c7ebe3994e4e0e947e2cedef35a480"
format_stamp: "Formatted at 2026-08-12 06:17:06 on dist-test-slave-bxbt"
I20260812 06:17:06.283063  4677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:06.297667  4677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:06.298177  4677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:06.298712  4677 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:06.300125  4677 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:06.300181  4677 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:06.300252  4677 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:06.300294  4677 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:06.308422  4677 rpc_server.cc:307] RPC server started. Bound to: 127.4.145.65:36011
I20260812 06:17:06.308454  4836 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.145.65:36011 every 8 connection(s)
I20260812 06:17:06.318813  4837 heartbeater.cc:344] Connected to a master server at 127.4.145.126:37717
I20260812 06:17:06.319125  4837 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:06.319592  4837 heartbeater.cc:507] Master 127.4.145.126:37717 requested a full tablet report, sending...
I20260812 06:17:06.321041  4707 ts_manager.cc:194] Registered new tserver with Master: c8c7ebe3994e4e0e947e2cedef35a480 (127.4.145.65:36011)
I20260812 06:17:06.321385  4677 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012178427s
I20260812 06:17:06.322292  4707 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48200
I20260812 06:17:06.331530  4707 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48214:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:06.346514  4801 tablet_service.cc:1511] Processing CreateTablet for tablet c0b0b0b2f9404f57bc623a696ea9d07b (DEFAULT_TABLE table=heavy-update-compaction-test [id=cb6f6bf9ba45411f950d05b739d639c8]), partition=
I20260812 06:17:06.347007  4801 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c0b0b0b2f9404f57bc623a696ea9d07b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:06.349678  4849 tablet_bootstrap.cc:492] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Bootstrap starting.
I20260812 06:17:06.350637  4849 tablet_bootstrap.cc:654] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:06.351876  4849 tablet_bootstrap.cc:492] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: No bootstrap required, opened a new log
I20260812 06:17:06.351992  4849 ts_tablet_manager.cc:1403] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:06.352751  4849 raft_consensus.cc:359] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8c7ebe3994e4e0e947e2cedef35a480" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 36011 } }
I20260812 06:17:06.352859  4849 raft_consensus.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:06.352883  4849 raft_consensus.cc:740] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c8c7ebe3994e4e0e947e2cedef35a480, State: Initialized, Role: FOLLOWER
I20260812 06:17:06.353060  4849 consensus_queue.cc:260] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [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: "c8c7ebe3994e4e0e947e2cedef35a480" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 36011 } }
I20260812 06:17:06.353154  4849 raft_consensus.cc:399] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:06.353205  4849 raft_consensus.cc:493] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:06.353302  4849 raft_consensus.cc:3060] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:06.354321  4849 raft_consensus.cc:515] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8c7ebe3994e4e0e947e2cedef35a480" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 36011 } }
I20260812 06:17:06.354492  4849 leader_election.cc:304] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [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: c8c7ebe3994e4e0e947e2cedef35a480; no voters: 
I20260812 06:17:06.354728  4849 leader_election.cc:290] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:06.354833  4851 raft_consensus.cc:2804] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:06.355055  4851 raft_consensus.cc:697] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 1 LEADER]: Becoming Leader. State: Replica: c8c7ebe3994e4e0e947e2cedef35a480, State: Running, Role: LEADER
I20260812 06:17:06.355095  4849 ts_tablet_manager.cc:1434] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:06.355465  4837 heartbeater.cc:499] Master 127.4.145.126:37717 was elected leader, sending a full tablet report...
I20260812 06:17:06.355947  4851 consensus_queue.cc:237] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [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: "c8c7ebe3994e4e0e947e2cedef35a480" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 36011 } }
I20260812 06:17:06.359031  4707 catalog_manager.cc:5719] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 reported cstate change: term changed from 0 to 1, leader changed from <none> to c8c7ebe3994e4e0e947e2cedef35a480 (127.4.145.65). New cstate: current_term: 1 leader_uuid: "c8c7ebe3994e4e0e947e2cedef35a480" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c8c7ebe3994e4e0e947e2cedef35a480" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 36011 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:06.422755  4677 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.056s	user 0.023s	sys 0.004s
I20260812 06:17:06.559759  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=19.054940
I20260812 06:17:06.738991  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.179s	user 0.143s	sys 0.033s Metrics: {"bytes_written":12717735,"cfile_init":1,"compiler_manager_pool.queue_time_us":217,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":834,"drs_written":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44275,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":312704,"thread_start_us":146,"threads_started":1,"update_count":1550}
I20260812 06:17:06.740327  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 20743880 bytes of WAL
I20260812 06:17:06.740644  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 2 log segments from log reader
I20260812 06:17:06.740711  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000001 (ops 1-6)
I20260812 06:17:06.740760  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000002 (ops 7-11)
I20260812 06:17:06.745720  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:06.746124  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:06.765440  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.019s	user 0.003s	sys 0.014s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.766022  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): 16411396 bytes on disk
I20260812 06:17:06.766683  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.767138  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:06.781584  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5428,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:06.782092  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:06.949115  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.167s	user 0.123s	sys 0.043s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":594,"lbm_read_time_us":12327,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27480,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":333,"threads_started":5,"update_count":2500}
I20260812 06:17:06.949805  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:06.989570  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15087,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:06.990247  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.006928  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6297,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.007388  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.144085  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.136s	user 0.084s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1251,"lbm_read_time_us":7459,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27678,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:17:07.144588  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:07.190853  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.046s	user 0.011s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13197,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.191412  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.202346  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3924,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.202942  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.323318  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.120s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":487,"lbm_read_time_us":8126,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23014,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:17:07.323951  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:07.367995  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.044s	user 0.014s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16865,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.368450  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.379612  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.380237  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.501211  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.121s	user 0.106s	sys 0.014s 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":946,"lbm_read_time_us":8998,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22844,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.501724  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:07.544591  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.043s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17330,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.545135  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.556449  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.556938  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.700078  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.143s	user 0.091s	sys 0.051s 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":110,"lbm_read_time_us":11070,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23736,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:07.700630  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:07.737694  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16645,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:07.738350  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.755158  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.017s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6050,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.755666  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.892165  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.136s	user 0.090s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":999,"lbm_read_time_us":6983,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28077,"lbm_writes_lt_1ms":443,"mutex_wait_us":371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:07.892892  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:07.928537  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.035s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15569,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:07.929152  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:07.945302  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5972,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":27520,"update_count":450}
I20260812 06:17:07.945812  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:07.975958  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.030s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1209,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1853,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:07.976868  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 112692365 bytes of WAL
I20260812 06:17:07.977138  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 11 log segments from log reader
I20260812 06:17:07.977191  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000003 (ops 12-16)
I20260812 06:17:07.977229  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000004 (ops 17-21)
I20260812 06:17:07.977295  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000005 (ops 22-26)
I20260812 06:17:07.977366  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000006 (ops 27-31)
I20260812 06:17:07.977411  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000007 (ops 32-36)
I20260812 06:17:07.977449  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000008 (ops 37-41)
I20260812 06:17:07.977510  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000009 (ops 42-46)
I20260812 06:17:07.977550  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000010 (ops 47-51)
I20260812 06:17:07.977589  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000011 (ops 52-56)
I20260812 06:17:07.977627  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000012 (ops 57-61)
I20260812 06:17:07.977666  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000013 (ops 62-66)
I20260812 06:17:08.001863  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.025s	user 0.003s	sys 0.020s Metrics: {}
I20260812 06:17:08.002332  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): 472 bytes on disk
I20260812 06:17:08.002874  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:08.003355  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=3.181125
I20260812 06:17:08.018419  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":5005191,"delete_count":0,"lbm_write_time_us":5813,"lbm_writes_lt_1ms":125,"reinsert_count":0,"update_count":610}
I20260812 06:17:08.018959  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 12017927 bytes of WAL
I20260812 06:17:08.019240  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 1 log segments from log reader
I20260812 06:17:08.019305  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000014 (ops 67-71)
I20260812 06:17:08.022267  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:08.022662  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.037212  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.014s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3200105,"delete_count":0,"lbm_write_time_us":5154,"lbm_writes_lt_1ms":81,"reinsert_count":0,"update_count":390}
I20260812 06:17:08.037667  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:08.199410  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.162s	user 0.116s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877310,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2117,"lbm_read_time_us":10757,"lbm_reads_lt_1ms":666,"lbm_write_time_us":31283,"lbm_writes_lt_1ms":643,"mutex_wait_us":1715,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:17:08.200002  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=14.095187
I20260812 06:17:08.257125  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.057s	user 0.024s	sys 0.031s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":25036,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.257673  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.269873  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.270324  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:08.414171  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.144s	user 0.110s	sys 0.032s 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":145,"lbm_read_time_us":8669,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30241,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:08.414676  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:08.458782  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.044s	user 0.013s	sys 0.027s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17816,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:08.459311  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.473258  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4153,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:17:08.473750  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.483999  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3856508,"delete_count":0,"lbm_write_time_us":3856,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:17:08.484536  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:08.636293  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.152s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":122,"lbm_read_time_us":10852,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30429,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:08.636978  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:08.673910  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.037s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15905,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:08.674400  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.695094  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.020s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.695592  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:08.828766  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.133s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":8353,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23762,"lbm_writes_lt_1ms":443,"mutex_wait_us":55,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:08.829409  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:08.869812  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.040s	user 0.015s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14800,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:08.870374  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:08.882433  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4098,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:08.883045  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.030637  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.147s	user 0.109s	sys 0.035s 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":153,"lbm_read_time_us":10009,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24420,"lbm_writes_lt_1ms":443,"mutex_wait_us":277,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:09.031358  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:09.067556  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.036s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15379,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:09.068246  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.083154  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5220,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.083758  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.215031  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.131s	user 0.118s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":74,"lbm_read_time_us":7744,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27564,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:17:09.215987  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:09.256268  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17699,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.256916  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.272357  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.273129  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.399328  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.126s	user 0.085s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":285,"lbm_read_time_us":7900,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25320,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":55040,"update_count":2000}
I20260812 06:17:09.399953  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:09.446830  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.047s	user 0.017s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18343,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:09.447333  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.458163  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.459018  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.486523  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.027s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":178,"dirs.run_wall_time_us":1235,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1548,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:09.487277  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 120553399 bytes of WAL
I20260812 06:17:09.487550  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 12 log segments from log reader
I20260812 06:17:09.487598  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000015 (ops 72-76)
I20260812 06:17:09.487629  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000016 (ops 77-81)
I20260812 06:17:09.487708  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000017 (ops 82-86)
I20260812 06:17:09.487749  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000018 (ops 87-90)
I20260812 06:17:09.487798  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000019 (ops 91-95)
I20260812 06:17:09.487841  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000020 (ops 96-100)
I20260812 06:17:09.487881  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000021 (ops 101-104)
I20260812 06:17:09.487919  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000022 (ops 105-109)
I20260812 06:17:09.487959  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000023 (ops 110-114)
I20260812 06:17:09.487999  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000024 (ops 115-119)
I20260812 06:17:09.488037  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000025 (ops 120-124)
I20260812 06:17:09.488076  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000026 (ops 125-129)
I20260812 06:17:09.512740  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.025s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:09.513211  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): 481 bytes on disk
I20260812 06:17:09.513667  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) 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:17:09.514168  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=3.181125
I20260812 06:17:09.527377  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:09.527889  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 12017954 bytes of WAL
I20260812 06:17:09.528103  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 1 log segments from log reader
I20260812 06:17:09.528147  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000027 (ops 130-134)
I20260812 06:17:09.530294  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:09.530591  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.542094  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3741,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.542925  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.726625  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.183s	user 0.133s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3396,"lbm_read_time_us":10663,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37698,"lbm_writes_lt_1ms":643,"mutex_wait_us":2726,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15488,"thread_start_us":73,"threads_started":1,"update_count":3000}
I20260812 06:17:09.727130  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=14.095187
I20260812 06:17:09.774308  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.047s	user 0.016s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18544,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.774852  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.787079  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.787771  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:09.933593  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.146s	user 0.104s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":333,"lbm_read_time_us":10514,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28004,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:09.934625  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:09.967270  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.032s	user 0.016s	sys 0.012s Metrics: {"bytes_written":13086952,"delete_count":0,"lbm_write_time_us":14132,"lbm_writes_lt_1ms":322,"reinsert_count":0,"update_count":1595}
I20260812 06:17:09.968070  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:09.985551  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.017s	user 0.011s	sys 0.001s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":5031,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:17:09.986124  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:10.138129  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.152s	user 0.108s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672260,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":199,"lbm_read_time_us":9965,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25038,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:17:10.138967  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:10.176072  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.037s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15534,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.176712  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.202924  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5587,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.203454  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.222146  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.222771  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:10.406574  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.184s	user 0.121s	sys 0.053s 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":468,"lbm_read_time_us":10896,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29113,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:17:10.407379  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=14.095187
I20260812 06:17:10.455458  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.048s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20594,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.456034  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.467550  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.468163  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:10.641788  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.173s	user 0.118s	sys 0.044s 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":445,"lbm_read_time_us":11523,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28456,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21632,"update_count":2500}
I20260812 06:17:10.642606  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=11.118625
I20260812 06:17:10.676460  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.034s	user 0.014s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14232,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:10.677404  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.692587  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5460,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.693432  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:10.822434  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.129s	user 0.103s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":7106,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24589,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2000}
I20260812 06:17:10.823160  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=10.126437
I20260812 06:17:10.854277  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.031s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12430562,"delete_count":0,"lbm_write_time_us":13234,"lbm_writes_lt_1ms":306,"mutex_wait_us":75,"reinsert_count":0,"update_count":1515}
I20260812 06:17:10.854990  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.868001  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4476,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:10.868721  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:10.901341  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushMRSOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.032s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":249,"dirs.run_wall_time_us":1286,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1582,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:10.902022  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): free 116849782 bytes of WAL
I20260812 06:17:10.902251  4778 log_reader.cc:385] T c0b0b0b2f9404f57bc623a696ea9d07b: removed 12 log segments from log reader
I20260812 06:17:10.902319  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000028 (ops 135-139)
I20260812 06:17:10.902369  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000029 (ops 140-144)
I20260812 06:17:10.902427  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000030 (ops 145-148)
I20260812 06:17:10.902474  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000031 (ops 149-153)
I20260812 06:17:10.902513  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000032 (ops 154-158)
I20260812 06:17:10.902554  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000033 (ops 159-162)
I20260812 06:17:10.902592  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000034 (ops 163-167)
I20260812 06:17:10.902630  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000035 (ops 168-172)
I20260812 06:17:10.902671  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000036 (ops 173-176)
I20260812 06:17:10.902711  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000037 (ops 177-181)
I20260812 06:17:10.902750  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000038 (ops 182-186)
I20260812 06:17:10.902796  4778 log.cc:1079] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/c0b0b0b2f9404f57bc623a696ea9d07b/wal-000000039 (ops 187-191)
I20260812 06:17:10.927376  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: LogGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:10.927886  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b): 463 bytes on disk
I20260812 06:17:10.928367  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: UndoDeltaBlockGCOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.928997  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=3.181125
I20260812 06:17:10.944698  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.016s	user 0.002s	sys 0.013s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6404,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:10.945149  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=2.188937
I20260812 06:17:10.955027  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3658,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.955569  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=1.000000
I20260812 06:17:11.131651  4677 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.709s	user 1.789s	sys 0.137s
I20260812 06:17:11.134922  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: MajorDeltaCompactionOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.179s	user 0.140s	sys 0.033s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2041,"lbm_read_time_us":13250,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34373,"lbm_writes_lt_1ms":643,"mutex_wait_us":1061,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":38016,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:17:11.135757  4838 maintenance_manager.cc:419] P c8c7ebe3994e4e0e947e2cedef35a480: Scheduling FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b): perf score=14.095187
I20260812 06:17:11.162113  4677 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.030s	user 0.001s	sys 0.003s
I20260812 06:17:11.163017  4677 tablet_server.cc:179] TabletServer@127.4.145.65:0 shutting down...
I20260812 06:17:11.183005  4778 maintenance_manager.cc:643] P c8c7ebe3994e4e0e947e2cedef35a480: FlushDeltaMemStoresOp(c0b0b0b2f9404f57bc623a696ea9d07b) complete. Timing: real 0.047s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:11.183647  4677 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:11.184237  4677 tablet_replica.cc:333] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480: stopping tablet replica
I20260812 06:17:11.184443  4677 raft_consensus.cc:2243] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:11.184628  4677 raft_consensus.cc:2272] T c0b0b0b2f9404f57bc623a696ea9d07b P c8c7ebe3994e4e0e947e2cedef35a480 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:11.199555  4677 tablet_server.cc:196] TabletServer@127.4.145.65:0 shutdown complete.
I20260812 06:17:11.204524  4677 master.cc:562] Master@127.4.145.126:37717 shutting down...
I20260812 06:17:11.209017  4677 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:11.209249  4677 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:11.209347  4677 tablet_replica.cc:333] T 00000000000000000000000000000000 P b42ce38bc9374892a4defc9f9c1638bc: stopping tablet replica
I20260812 06:17:11.221882  4677 master.cc:584] Master@127.4.145.126:37717 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5172 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:11.314708  4677 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.4.145.126:39893
I20260812 06:17:11.315207  4677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.317363  4868 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.317456  4869 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.317494  4871 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.317870  4677 server_base.cc:1061] running on GCE node
I20260812 06:17:11.318058  4677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.318091  4677 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.318105  4677 hybrid_clock.cc:648] HybridClock initialized: now 1786515431318106 us; error 0 us; skew 500 ppm
I20260812 06:17:11.318938  4677 webserver.cc:533] Webserver started at http://127.4.145.126:45869/ using document root <none> and password file <none>
I20260812 06:17:11.319073  4677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.319113  4677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.319166  4677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.319514  4677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/master-0-root/instance:
uuid: "a759d9807a2e4a38a29ee02d078e2d3c"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-bxbt"
I20260812 06:17:11.321132  4677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:11.322037  4876 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.322301  4677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:11.322368  4677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/master-0-root
uuid: "a759d9807a2e4a38a29ee02d078e2d3c"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-bxbt"
I20260812 06:17:11.322466  4677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.331938  4677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.332357  4677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.336652  4677 rpc_server.cc:307] RPC server started. Bound to: 127.4.145.126:39893
I20260812 06:17:11.341197  4929 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.345950  4928 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.145.126:39893 every 8 connection(s)
I20260812 06:17:11.353590  4929 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c: Bootstrap starting.
I20260812 06:17:11.354525  4929 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.355742  4929 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c: No bootstrap required, opened a new log
I20260812 06:17:11.356225  4929 raft_consensus.cc:359] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER }
I20260812 06:17:11.356376  4929 raft_consensus.cc:385] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.356434  4929 raft_consensus.cc:740] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: a759d9807a2e4a38a29ee02d078e2d3c, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.356622  4929 consensus_queue.cc:260] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [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: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER }
I20260812 06:17:11.356740  4929 raft_consensus.cc:399] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.356791  4929 raft_consensus.cc:493] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.356860  4929 raft_consensus.cc:3060] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.357626  4929 raft_consensus.cc:515] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER }
I20260812 06:17:11.357785  4929 leader_election.cc:304] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [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: a759d9807a2e4a38a29ee02d078e2d3c; no voters: 
I20260812 06:17:11.358038  4929 leader_election.cc:290] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.358198  4932 raft_consensus.cc:2804] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.358451  4932 raft_consensus.cc:697] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 1 LEADER]: Becoming Leader. State: Replica: a759d9807a2e4a38a29ee02d078e2d3c, State: Running, Role: LEADER
I20260812 06:17:11.358553  4929 sys_catalog.cc:565] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:11.358619  4932 consensus_queue.cc:237] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [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: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER }
I20260812 06:17:11.359108  4934 sys_catalog.cc:455] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [sys.catalog]: SysCatalogTable state changed. Reason: New leader a759d9807a2e4a38a29ee02d078e2d3c. Latest consensus state: current_term: 1 leader_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER } }
I20260812 06:17:11.359089  4933 sys_catalog.cc:455] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "a759d9807a2e4a38a29ee02d078e2d3c" member_type: VOTER } }
I20260812 06:17:11.359203  4934 sys_catalog.cc:458] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.359213  4933 sys_catalog.cc:458] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:11.359707  4937 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:11.360435  4937 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:11.360772  4677 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:11.362428  4937 catalog_manager.cc:1383] Generated new cluster ID: 6490a9b87cd3487bada3790b484e6a25
I20260812 06:17:11.362489  4937 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:11.371246  4937 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:11.371917  4937 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:11.376829  4937 catalog_manager.cc:6092] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c: Generated new TSK 0
I20260812 06:17:11.377022  4937 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:11.393277  4677 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:11.395402  4950 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.395402  4953 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:11.395577  4951 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:11.395780  4677 server_base.cc:1061] running on GCE node
I20260812 06:17:11.395968  4677 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:11.396025  4677 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:11.396061  4677 hybrid_clock.cc:648] HybridClock initialized: now 1786515431396060 us; error 0 us; skew 500 ppm
I20260812 06:17:11.397068  4677 webserver.cc:533] Webserver started at http://127.4.145.65:36263/ using document root <none> and password file <none>
I20260812 06:17:11.397269  4677 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:11.397344  4677 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:11.397436  4677 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:11.397867  4677 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/instance:
uuid: "8c6447c07d074069a92eec40a99600bd"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-bxbt"
I20260812 06:17:11.399504  4677 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:11.400626  4958 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.400918  4677 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:11.401010  4677 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root
uuid: "8c6447c07d074069a92eec40a99600bd"
format_stamp: "Formatted at 2026-08-12 06:17:11 on dist-test-slave-bxbt"
I20260812 06:17:11.401103  4677 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:11.422941  4677 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:11.423425  4677 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:11.423869  4677 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:11.424378  4677 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:11.424444  4677 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.424506  4677 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:11.424557  4677 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:11.428826  4677 rpc_server.cc:307] RPC server started. Bound to: 127.4.145.65:46239
I20260812 06:17:11.428857  5021 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.4.145.65:46239 every 8 connection(s)
I20260812 06:17:11.437351  5022 heartbeater.cc:344] Connected to a master server at 127.4.145.126:39893
I20260812 06:17:11.437615  5022 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:11.437922  5022 heartbeater.cc:507] Master 127.4.145.126:39893 requested a full tablet report, sending...
I20260812 06:17:11.438647  4893 ts_manager.cc:194] Registered new tserver with Master: 8c6447c07d074069a92eec40a99600bd (127.4.145.65:46239)
I20260812 06:17:11.439194  4677 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009935207s
I20260812 06:17:11.439481  4893 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40362
I20260812 06:17:11.446856  4893 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40374:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:11.456758  4986 tablet_service.cc:1511] Processing CreateTablet for tablet 75963af588b94e2eb93397f658c7907e (DEFAULT_TABLE table=heavy-update-compaction-test [id=5664b50a3a354e059d30f6d3a2113b2a]), partition=
I20260812 06:17:11.457093  4986 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 75963af588b94e2eb93397f658c7907e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:11.459357  5034 tablet_bootstrap.cc:492] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Bootstrap starting.
I20260812 06:17:11.460311  5034 tablet_bootstrap.cc:654] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:11.461602  5034 tablet_bootstrap.cc:492] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: No bootstrap required, opened a new log
I20260812 06:17:11.461683  5034 ts_tablet_manager.cc:1403] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:11.462193  5034 raft_consensus.cc:359] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c6447c07d074069a92eec40a99600bd" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 46239 } }
I20260812 06:17:11.462291  5034 raft_consensus.cc:385] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:11.462313  5034 raft_consensus.cc:740] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8c6447c07d074069a92eec40a99600bd, State: Initialized, Role: FOLLOWER
I20260812 06:17:11.462486  5034 consensus_queue.cc:260] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [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: "8c6447c07d074069a92eec40a99600bd" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 46239 } }
I20260812 06:17:11.462565  5034 raft_consensus.cc:399] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:11.462630  5034 raft_consensus.cc:493] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:11.462694  5034 raft_consensus.cc:3060] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:11.463605  5034 raft_consensus.cc:515] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c6447c07d074069a92eec40a99600bd" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 46239 } }
I20260812 06:17:11.463794  5034 leader_election.cc:304] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [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: 8c6447c07d074069a92eec40a99600bd; no voters: 
I20260812 06:17:11.464040  5034 leader_election.cc:290] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:11.464203  5036 raft_consensus.cc:2804] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:11.464373  5034 ts_tablet_manager.cc:1434] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.002s
I20260812 06:17:11.464427  5022 heartbeater.cc:499] Master 127.4.145.126:39893 was elected leader, sending a full tablet report...
I20260812 06:17:11.464443  5036 raft_consensus.cc:697] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 1 LEADER]: Becoming Leader. State: Replica: 8c6447c07d074069a92eec40a99600bd, State: Running, Role: LEADER
I20260812 06:17:11.464635  5036 consensus_queue.cc:237] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [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: "8c6447c07d074069a92eec40a99600bd" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 46239 } }
I20260812 06:17:11.466104  4892 catalog_manager.cc:5719] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd reported cstate change: term changed from 0 to 1, leader changed from <none> to 8c6447c07d074069a92eec40a99600bd (127.4.145.65). New cstate: current_term: 1 leader_uuid: "8c6447c07d074069a92eec40a99600bd" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8c6447c07d074069a92eec40a99600bd" member_type: VOTER last_known_addr { host: "127.4.145.65" port: 46239 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:11.524292  4677 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.018s	sys 0.004s
I20260812 06:17:11.679867  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushMRSOp(75963af588b94e2eb93397f658c7907e): perf score=19.054940
I20260812 06:17:11.836252  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushMRSOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.156s	user 0.111s	sys 0.044s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":306,"dirs.run_wall_time_us":955,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39794,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:11.836962  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 20743880 bytes of WAL
I20260812 06:17:11.837244  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 2 log segments from log reader
I20260812 06:17:11.837357  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000001 (ops 1-6)
I20260812 06:17:11.837435  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000002 (ops 7-11)
I20260812 06:17:11.841799  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:11.842245  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e): 16411396 bytes on disk
I20260812 06:17:11.842672  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.843173  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:11.861845  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.019s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4254,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":500}
I20260812 06:17:11.862277  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:11.872750  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3815,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.873238  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:12.041890  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.168s	user 0.118s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1048,"lbm_read_time_us":11968,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30051,"lbm_writes_lt_1ms":543,"mutex_wait_us":80,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"thread_start_us":331,"threads_started":5,"update_count":2500}
I20260812 06:17:12.042485  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=11.118625
I20260812 06:17:12.076858  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.034s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14497,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.077381  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:12.101116  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.024s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.101549  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:12.111358  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3542,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.111882  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:12.283111  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.171s	user 0.118s	sys 0.049s 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":422,"lbm_read_time_us":11697,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32160,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:12.283934  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=12.110812
I20260812 06:17:12.327152  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":13743339,"delete_count":0,"lbm_write_time_us":18871,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:17:12.327639  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=1.196750
I20260812 06:17:12.338088  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":3466,"lbm_writes_lt_1ms":68,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":325}
I20260812 06:17:12.338541  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:12.484133  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.145s	user 0.094s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672246,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":9055,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25376,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.484820  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=11.118625
I20260812 06:17:12.522337  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.037s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15836,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:12.523021  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:12.542022  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5978,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.542532  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:12.679934  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.137s	user 0.109s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":626,"lbm_read_time_us":7185,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26860,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2000}
I20260812 06:17:12.680718  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:12.717097  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.036s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.717615  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:12.733968  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.734577  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:12.864022  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.129s	user 0.089s	sys 0.040s 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":208,"lbm_read_time_us":8503,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26088,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2000}
I20260812 06:17:12.864764  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:12.904491  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.040s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.905197  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:13.017153  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.112s	user 0.103s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":194,"lbm_read_time_us":5802,"lbm_reads_lt_1ms":363,"lbm_write_time_us":21877,"lbm_writes_lt_1ms":343,"mutex_wait_us":67,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":1500}
I20260812 06:17:13.017902  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:13.076850  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.059s	user 0.027s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19583,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:13.077616  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.092401  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.092859  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushMRSOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:13.118680  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushMRSOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.026s	user 0.021s	sys 0.003s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":97,"dirs.run_cpu_time_us":258,"dirs.run_wall_time_us":1197,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1594,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:13.119305  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 112692374 bytes of WAL
I20260812 06:17:13.119547  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 11 log segments from log reader
I20260812 06:17:13.119593  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000003 (ops 12-16)
I20260812 06:17:13.119622  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000004 (ops 17-21)
I20260812 06:17:13.119724  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000005 (ops 22-26)
I20260812 06:17:13.119788  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000006 (ops 27-31)
I20260812 06:17:13.119850  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000007 (ops 32-36)
I20260812 06:17:13.119889  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000008 (ops 37-41)
I20260812 06:17:13.119931  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000009 (ops 42-46)
I20260812 06:17:13.119971  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000010 (ops 47-51)
I20260812 06:17:13.120009  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000011 (ops 52-56)
I20260812 06:17:13.120047  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000012 (ops 57-61)
I20260812 06:17:13.120085  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000013 (ops 62-66)
I20260812 06:17:13.145896  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:13.146946  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=3.181125
I20260812 06:17:13.174047  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.027s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4430855,"delete_count":0,"lbm_write_time_us":5039,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:17:13.174501  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 11564875 bytes of WAL
I20260812 06:17:13.174706  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 1 log segments from log reader
I20260812 06:17:13.174767  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000014 (ops 67-70)
I20260812 06:17:13.177024  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:13.177369  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.187212  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3588,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:17:13.187786  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:13.389326  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.201s	user 0.128s	sys 0.073s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877335,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":360,"lbm_read_time_us":13931,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35192,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"thread_start_us":111,"threads_started":1,"update_count":3000}
I20260812 06:17:13.390084  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e): 461 bytes on disk
I20260812 06:17:13.390596  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.391166  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:13.452364  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.061s	user 0.045s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20840,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.453047  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.481452  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.028s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5855,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.482007  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.492779  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.493458  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:13.695779  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.202s	user 0.132s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":189,"lbm_read_time_us":14766,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31928,"lbm_writes_lt_1ms":643,"mutex_wait_us":43,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18048,"update_count":3000}
I20260812 06:17:13.696542  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:13.739372  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.043s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19097,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.739982  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.760443  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.020s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6043,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.760972  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:13.924062  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.163s	user 0.123s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":10224,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29035,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:13.924788  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:13.968199  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.043s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19505,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.968819  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:13.979913  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.980546  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:14.176182  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.195s	user 0.131s	sys 0.064s 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":162,"lbm_read_time_us":12892,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34132,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:17:14.176937  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:14.239169  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.062s	user 0.038s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22869,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.239780  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:14.250401  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4175,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.250842  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:14.442363  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.191s	user 0.143s	sys 0.048s 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":430,"lbm_read_time_us":12110,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31162,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":2500}
I20260812 06:17:14.443245  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:14.477182  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.478016  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:14.495221  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6029,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.495934  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:14.643741  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.148s	user 0.115s	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":1074,"lbm_read_time_us":9887,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27699,"lbm_writes_lt_1ms":443,"mutex_wait_us":316,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:14.644335  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:14.684226  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.040s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14552,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:14.684711  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:14.696700  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4330,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.697510  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushMRSOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:14.734921  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushMRSOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.037s	user 0.032s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":142,"dirs.run_wall_time_us":1207,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2021,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:14.735754  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 120553388 bytes of WAL
I20260812 06:17:14.736014  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 12 log segments from log reader
I20260812 06:17:14.736095  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000015 (ops 71-75)
I20260812 06:17:14.736151  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000016 (ops 76-80)
I20260812 06:17:14.736191  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000017 (ops 81-84)
I20260812 06:17:14.736234  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000018 (ops 85-89)
I20260812 06:17:14.736282  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000019 (ops 90-94)
I20260812 06:17:14.736318  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000020 (ops 95-99)
I20260812 06:17:14.736357  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000021 (ops 100-104)
I20260812 06:17:14.736395  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000022 (ops 105-108)
I20260812 06:17:14.736430  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000023 (ops 109-113)
I20260812 06:17:14.736469  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000024 (ops 114-118)
I20260812 06:17:14.736505  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000025 (ops 119-123)
I20260812 06:17:14.736542  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000026 (ops 124-128)
I20260812 06:17:14.762420  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:14.763093  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e): 482 bytes on disk
I20260812 06:17:14.763731  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:17:14.764281  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=6.157687
I20260812 06:17:14.793200  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.029s	user 0.020s	sys 0.000s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9531,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:14.793678  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:14.965482  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.172s	user 0.132s	sys 0.038s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":697,"lbm_read_time_us":12552,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33871,"lbm_writes_lt_1ms":643,"mutex_wait_us":259,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":430,"threads_started":1,"update_count":3000}
I20260812 06:17:14.966259  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:15.010888  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.044s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20080,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.012365  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:15.028946  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5219,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.029378  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:15.172508  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.143s	user 0.111s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":370,"lbm_read_time_us":8837,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26029,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:17:15.173085  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:15.225708  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.052s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.226271  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:15.237612  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.238073  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:15.391779  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.154s	user 0.105s	sys 0.038s 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":894,"lbm_read_time_us":9808,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28382,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:17:15.392493  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=14.095187
I20260812 06:17:15.445232  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.053s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21095,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.445770  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:15.457217  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.457702  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:15.612886  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.155s	user 0.119s	sys 0.031s 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":533,"lbm_read_time_us":10475,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28529,"lbm_writes_lt_1ms":543,"mutex_wait_us":267,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2500}
I20260812 06:17:15.613643  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=12.110812
I20260812 06:17:15.648273  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.034s	user 0.022s	sys 0.012s Metrics: {"bytes_written":13702313,"delete_count":0,"lbm_write_time_us":15043,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1670}
I20260812 06:17:15.648829  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=1.196750
I20260812 06:17:15.658790  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3509,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:17:15.659235  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:15.811801  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.152s	user 0.095s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672246,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":607,"lbm_read_time_us":9316,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25393,"lbm_writes_lt_1ms":443,"mutex_wait_us":252,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2000}
I20260812 06:17:15.812282  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=11.118625
I20260812 06:17:15.847823  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.035s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16025,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:15.848658  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:15.865021  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.016s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5045,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.865614  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:15.994721  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.129s	user 0.093s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":441,"lbm_read_time_us":7956,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23832,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:17:15.995594  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:16.038851  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.043s	user 0.014s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17853,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.039599  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:16.057120  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.017s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5913,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.057731  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushMRSOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:16.109048  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushMRSOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.051s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1280,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1702,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:16.109776  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 121006699 bytes of WAL
I20260812 06:17:16.110002  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 12 log segments from log reader
I20260812 06:17:16.110050  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000027 (ops 129-133)
I20260812 06:17:16.110080  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000028 (ops 134-138)
I20260812 06:17:16.110146  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000029 (ops 139-143)
I20260812 06:17:16.110176  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000030 (ops 144-148)
I20260812 06:17:16.110229  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000031 (ops 149-152)
I20260812 06:17:16.110266  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000032 (ops 153-157)
I20260812 06:17:16.110324  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000033 (ops 158-162)
I20260812 06:17:16.110365  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000034 (ops 163-167)
I20260812 06:17:16.110405  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000035 (ops 168-172)
I20260812 06:17:16.110445  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000036 (ops 173-177)
I20260812 06:17:16.110482  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000037 (ops 178-182)
I20260812 06:17:16.110522  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000038 (ops 183-187)
I20260812 06:17:16.136641  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:16.137166  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e): 473 bytes on disk
I20260812 06:17:16.137813  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: UndoDeltaBlockGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.138402  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=7.149875
I20260812 06:17:16.158175  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8489,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:17:16.158639  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling LogGCOp(75963af588b94e2eb93397f658c7907e): free 12017952 bytes of WAL
I20260812 06:17:16.158857  4963 log_reader.cc:385] T 75963af588b94e2eb93397f658c7907e: removed 1 log segments from log reader
I20260812 06:17:16.158905  4963 log.cc:1079] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: Deleting log segment in path: /tmp/dist-test-taskIMFSv2/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515426131883-4677-0/minicluster-data/ts-0-root/wals/75963af588b94e2eb93397f658c7907e/wal-000000039 (ops 188-192)
I20260812 06:17:16.161399  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: LogGCOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:16.161880  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:16.196914  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.035s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5453,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:16.197475  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=2.188937
I20260812 06:17:16.209928  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.012s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.210570  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e): perf score=1.000000
I20260812 06:17:16.348368  4677 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.824s	user 1.821s	sys 0.108s
I20260812 06:17:16.444031  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: MajorDeltaCompactionOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.233s	user 0.151s	sys 0.081s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082274,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":699,"lbm_read_time_us":16738,"lbm_reads_lt_1ms":871,"lbm_write_time_us":41356,"lbm_writes_lt_1ms":843,"mutex_wait_us":46,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":19072,"thread_start_us":98,"threads_started":1,"update_count":4000}
I20260812 06:17:16.445200  5023 maintenance_manager.cc:419] P 8c6447c07d074069a92eec40a99600bd: Scheduling FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e): perf score=10.126437
I20260812 06:17:16.455608  4677 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.001s	sys 0.000s
I20260812 06:17:16.456147  4677 tablet_server.cc:179] TabletServer@127.4.145.65:0 shutting down...
I20260812 06:17:16.492962  4963 maintenance_manager.cc:643] P 8c6447c07d074069a92eec40a99600bd: FlushDeltaMemStoresOp(75963af588b94e2eb93397f658c7907e) complete. Timing: real 0.048s	user 0.030s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16145,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:16.493698  4677 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:16.494001  4677 tablet_replica.cc:333] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd: stopping tablet replica
I20260812 06:17:16.494167  4677 raft_consensus.cc:2243] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.494349  4677 raft_consensus.cc:2272] T 75963af588b94e2eb93397f658c7907e P 8c6447c07d074069a92eec40a99600bd [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.497747  4677 tablet_server.cc:196] TabletServer@127.4.145.65:0 shutdown complete.
I20260812 06:17:16.514249  4677 master.cc:562] Master@127.4.145.126:39893 shutting down...
I20260812 06:17:16.518038  4677 raft_consensus.cc:2243] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:16.518239  4677 raft_consensus.cc:2272] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:16.518344  4677 tablet_replica.cc:333] T 00000000000000000000000000000000 P a759d9807a2e4a38a29ee02d078e2d3c: stopping tablet replica
I20260812 06:17:16.530699  4677 master.cc:584] Master@127.4.145.126:39893 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5297 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10471 ms total)

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