[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:39.088723 11491 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.56.254:38673
I20260812 06:19:39.089704 11491 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:39.090287 11491 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:39.096624 11491 server_base.cc:1061] running on GCE node
W20260812 06:19:39.096704 11497 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.096843 11504 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.096957 11499 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.097409 11491 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.097498 11491 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:39.097527 11491 hybrid_clock.cc:648] HybridClock initialized: now 1786515579097526 us; error 0 us; skew 500 ppm
I20260812 06:19:39.099124 11491 webserver.cc:533] Webserver started at http://127.11.56.254:35207/ using document root <none> and password file <none>
I20260812 06:19:39.099602 11491 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.099656 11491 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.099838 11491 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.101418 11491 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/master-0-root/instance:
uuid: "2710b2103e8a4703838900845dbfdcbc"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-xt4k"
I20260812 06:19:39.104614 11491 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:39.106513 11513 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.107486 11491 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:39.107596 11491 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/master-0-root
uuid: "2710b2103e8a4703838900845dbfdcbc"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-xt4k"
I20260812 06:19:39.107683 11491 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:39.124306 11491 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.125002 11491 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:39.125162 11491 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.132735 11491 rpc_server.cc:307] RPC server started. Bound to: 127.11.56.254:38673
I20260812 06:19:39.132733 11618 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.56.254:38673 every 8 connection(s)
I20260812 06:19:39.135002 11621 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.140470 11621 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: Bootstrap starting.
I20260812 06:19:39.142810 11621 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.143700 11621 log.cc:826] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:39.145404 11621 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: No bootstrap required, opened a new log
I20260812 06:19:39.148123 11621 raft_consensus.cc:359] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER }
I20260812 06:19:39.148283 11621 raft_consensus.cc:385] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.148326 11621 raft_consensus.cc:740] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2710b2103e8a4703838900845dbfdcbc, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.148952 11621 consensus_queue.cc:260] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [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: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER }
I20260812 06:19:39.149107 11621 raft_consensus.cc:399] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.149173 11621 raft_consensus.cc:493] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.149298 11621 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.150063 11621 raft_consensus.cc:515] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER }
I20260812 06:19:39.150478 11621 leader_election.cc:304] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [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: 2710b2103e8a4703838900845dbfdcbc; no voters: 
I20260812 06:19:39.150766 11621 leader_election.cc:290] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.150939 11627 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.151154 11627 raft_consensus.cc:697] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 1 LEADER]: Becoming Leader. State: Replica: 2710b2103e8a4703838900845dbfdcbc, State: Running, Role: LEADER
I20260812 06:19:39.151547 11627 consensus_queue.cc:237] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [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: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER }
I20260812 06:19:39.151753 11621 sys_catalog.cc:565] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:39.153395 11630 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [sys.catalog]: SysCatalogTable state changed. Reason: New leader 2710b2103e8a4703838900845dbfdcbc. Latest consensus state: current_term: 1 leader_uuid: "2710b2103e8a4703838900845dbfdcbc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER } }
I20260812 06:19:39.153540 11630 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.153440 11628 sys_catalog.cc:455] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "2710b2103e8a4703838900845dbfdcbc" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2710b2103e8a4703838900845dbfdcbc" member_type: VOTER } }
I20260812 06:19:39.153803 11628 sys_catalog.cc:458] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.153900 11649 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:39.154014 11491 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:39.156149 11649 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:39.161506 11649 catalog_manager.cc:1383] Generated new cluster ID: 4c9865972e3a41deb0be99d8dce8d775
I20260812 06:19:39.161579 11649 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:39.183215 11649 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:39.184527 11649 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:39.200994 11649 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: Generated new TSK 0
I20260812 06:19:39.201858 11649 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:39.218797 11491 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.221607 11660 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.221650 11675 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:39.221658 11661 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:39.221895 11491 server_base.cc:1061] running on GCE node
I20260812 06:19:39.222069 11491 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.222112 11491 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:39.222126 11491 hybrid_clock.cc:648] HybridClock initialized: now 1786515579222126 us; error 0 us; skew 500 ppm
I20260812 06:19:39.223120 11491 webserver.cc:533] Webserver started at http://127.11.56.193:44515/ using document root <none> and password file <none>
I20260812 06:19:39.223284 11491 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.223336 11491 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.223417 11491 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.223790 11491 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/instance:
uuid: "8f4441542c29481095169430344b8365"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-xt4k"
I20260812 06:19:39.225265 11491 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:19:39.226199 11683 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.226447 11491 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:39.226526 11491 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root
uuid: "8f4441542c29481095169430344b8365"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-xt4k"
I20260812 06:19:39.226594 11491 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:39.241626 11491 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.242086 11491 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.242591 11491 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:39.243448 11491 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:39.243501 11491 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.243559 11491 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:39.243587 11491 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.250029 11491 rpc_server.cc:307] RPC server started. Bound to: 127.11.56.193:40807
I20260812 06:19:39.250084 11804 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.56.193:40807 every 8 connection(s)
I20260812 06:19:39.260185 11806 heartbeater.cc:344] Connected to a master server at 127.11.56.254:38673
I20260812 06:19:39.260470 11806 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:39.260978 11806 heartbeater.cc:507] Master 127.11.56.254:38673 requested a full tablet report, sending...
I20260812 06:19:39.262395 11545 ts_manager.cc:194] Registered new tserver with Master: 8f4441542c29481095169430344b8365 (127.11.56.193:40807)
I20260812 06:19:39.263274 11491 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012655271s
I20260812 06:19:39.263669 11545 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39340
I20260812 06:19:39.272626 11545 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39346:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:39.286181 11740 tablet_service.cc:1511] Processing CreateTablet for tablet c65bf492a6314c17aa61f2c10f8b626c (DEFAULT_TABLE table=heavy-update-compaction-test [id=172346635f9c4069ab4e11a081ba6e2b]), partition=
I20260812 06:19:39.286616 11740 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c65bf492a6314c17aa61f2c10f8b626c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.289031 11825 tablet_bootstrap.cc:492] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Bootstrap starting.
I20260812 06:19:39.290249 11825 tablet_bootstrap.cc:654] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.291549 11825 tablet_bootstrap.cc:492] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: No bootstrap required, opened a new log
I20260812 06:19:39.291692 11825 ts_tablet_manager.cc:1403] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:39.292126 11825 raft_consensus.cc:359] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f4441542c29481095169430344b8365" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 40807 } }
I20260812 06:19:39.292227 11825 raft_consensus.cc:385] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.292258 11825 raft_consensus.cc:740] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8f4441542c29481095169430344b8365, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.292413 11825 consensus_queue.cc:260] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [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: "8f4441542c29481095169430344b8365" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 40807 } }
I20260812 06:19:39.292491 11825 raft_consensus.cc:399] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.292534 11825 raft_consensus.cc:493] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.292590 11825 raft_consensus.cc:3060] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.293534 11825 raft_consensus.cc:515] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f4441542c29481095169430344b8365" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 40807 } }
I20260812 06:19:39.293726 11825 leader_election.cc:304] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [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: 8f4441542c29481095169430344b8365; no voters: 
I20260812 06:19:39.293955 11825 leader_election.cc:290] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.294211 11827 raft_consensus.cc:2804] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.294301 11825 ts_tablet_manager.cc:1434] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:39.294476 11827 raft_consensus.cc:697] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 1 LEADER]: Becoming Leader. State: Replica: 8f4441542c29481095169430344b8365, State: Running, Role: LEADER
I20260812 06:19:39.294687 11827 consensus_queue.cc:237] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [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: "8f4441542c29481095169430344b8365" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 40807 } }
I20260812 06:19:39.294752 11806 heartbeater.cc:499] Master 127.11.56.254:38673 was elected leader, sending a full tablet report...
I20260812 06:19:39.297328 11545 catalog_manager.cc:5719] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8f4441542c29481095169430344b8365 (127.11.56.193). New cstate: current_term: 1 leader_uuid: "8f4441542c29481095169430344b8365" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8f4441542c29481095169430344b8365" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 40807 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:39.368047 11491 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.061s	user 0.023s	sys 0.009s
I20260812 06:19:39.501076 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=19.054940
I20260812 06:19:39.679365 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.178s	user 0.136s	sys 0.036s Metrics: {"bytes_written":14276638,"cfile_init":1,"compiler_manager_pool.queue_time_us":192,"delete_count":0,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":229,"dirs.run_wall_time_us":915,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44432,"lbm_writes_lt_1ms":805,"mutex_wait_us":1120,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":247552,"thread_start_us":103,"threads_started":1,"update_count":1740}
I20260812 06:19:39.680779 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c): 16411393 bytes on disk
I20260812 06:19:39.681453 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.681964 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:39.696135 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3651388,"delete_count":0,"lbm_write_time_us":5274,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:19:39.696707 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling LogGCOp(c65bf492a6314c17aa61f2c10f8b626c): free 20743880 bytes of WAL
I20260812 06:19:39.697077 11690 log_reader.cc:385] T c65bf492a6314c17aa61f2c10f8b626c: removed 2 log segments from log reader
I20260812 06:19:39.697201 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000001 (ops 1-6)
I20260812 06:19:39.697304 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000002 (ops 7-11)
I20260812 06:19:39.702731 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: LogGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:39.703102 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.196750
I20260812 06:19:39.712299 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":3308,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:19:39.712759 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:39.879114 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.166s	user 0.122s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774755,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":891,"lbm_read_time_us":9925,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28437,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":308,"threads_started":5,"update_count":2500}
I20260812 06:19:39.879604 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:39.929893 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.050s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16093,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:39.930388 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:39.940665 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.941144 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.074512 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.133s	user 0.089s	sys 0.036s 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":166,"lbm_read_time_us":8254,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23944,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.075018 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:40.118611 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.043s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13806,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.119184 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:40.129354 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.129788 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.245136 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.115s	user 0.100s	sys 0.015s 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":117,"lbm_read_time_us":8860,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20619,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:40.245736 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:40.290261 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.044s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17355,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.290799 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:40.301252 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.302158 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.427696 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.125s	user 0.090s	sys 0.035s 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":580,"lbm_read_time_us":9133,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23418,"lbm_writes_lt_1ms":443,"mutex_wait_us":332,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35968,"update_count":2000}
I20260812 06:19:40.428177 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:40.480162 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.052s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13376,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.480772 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:40.490675 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3710,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.491122 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.628741 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.137s	user 0.090s	sys 0.046s 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":812,"lbm_read_time_us":10143,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23198,"lbm_writes_lt_1ms":443,"mutex_wait_us":262,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:40.629182 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:40.658792 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.029s	user 0.017s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12251,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.659273 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.758096 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.099s	user 0.052s	sys 0.046s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569748,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":227,"lbm_read_time_us":6659,"lbm_reads_lt_1ms":363,"lbm_write_time_us":18141,"lbm_writes_lt_1ms":343,"mutex_wait_us":31,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":1500}
I20260812 06:19:40.758605 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:40.806361 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.048s	user 0.032s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16772,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.806843 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:40.817261 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3685,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.817889 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:40.843665 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1291,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1245,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:40.844467 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling LogGCOp(c65bf492a6314c17aa61f2c10f8b626c): free 112692383 bytes of WAL
I20260812 06:19:40.844676 11690 log_reader.cc:385] T c65bf492a6314c17aa61f2c10f8b626c: removed 11 log segments from log reader
I20260812 06:19:40.844720 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000003 (ops 12-16)
I20260812 06:19:40.844748 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000004 (ops 17-21)
I20260812 06:19:40.844780 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000005 (ops 22-26)
I20260812 06:19:40.844810 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000006 (ops 27-31)
I20260812 06:19:40.844843 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000007 (ops 32-36)
I20260812 06:19:40.844877 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000008 (ops 37-41)
I20260812 06:19:40.844908 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000009 (ops 42-46)
I20260812 06:19:40.844941 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000010 (ops 47-51)
I20260812 06:19:40.844974 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000011 (ops 52-56)
I20260812 06:19:40.845005 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000012 (ops 57-61)
I20260812 06:19:40.845037 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000013 (ops 62-66)
I20260812 06:19:40.865619 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: LogGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:40.866010 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c): 447 bytes on disk
I20260812 06:19:40.866503 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.866966 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=3.181125
I20260812 06:19:40.880491 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":3874,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.880924 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:40.889935 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3193,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.890420 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:41.066422 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.176s	user 0.126s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877325,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":994,"lbm_read_time_us":12908,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31890,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":70,"threads_started":1,"update_count":3000}
I20260812 06:19:41.068641 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:41.157733 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.089s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20081,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.158233 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:41.173545 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5014,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.173980 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:41.322860 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.149s	user 0.108s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":963,"lbm_read_time_us":10197,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28879,"lbm_writes_lt_1ms":543,"mutex_wait_us":315,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:19:41.323338 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:41.365866 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.042s	user 0.026s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16979,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.366385 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:41.376153 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3580,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.376655 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:41.538813 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.162s	user 0.096s	sys 0.059s 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":1013,"lbm_read_time_us":9973,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27779,"lbm_writes_lt_1ms":543,"mutex_wait_us":298,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:41.539357 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:41.580035 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.041s	user 0.030s	sys 0.007s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17917,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.580529 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:41.734479 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.154s	user 0.097s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":564,"lbm_read_time_us":9218,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21832,"lbm_writes_lt_1ms":443,"mutex_wait_us":271,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:19:41.734979 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:41.787242 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.052s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409909,"delete_count":0,"lbm_write_time_us":24013,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.787768 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:41.799369 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.799849 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:41.962687 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.163s	user 0.092s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774695,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":115,"lbm_read_time_us":9458,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25010,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2500}
I20260812 06:19:41.963124 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:42.020709 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.057s	user 0.031s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26745,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.021234 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:42.033208 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4439,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.033681 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:42.179453 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.146s	user 0.115s	sys 0.029s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":756,"lbm_read_time_us":9576,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26094,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:42.180019 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:42.226518 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.046s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19700,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.227007 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:42.237725 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.011s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3921,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.238168 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:42.267213 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.029s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1257,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1582,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:42.267890 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling LogGCOp(c65bf492a6314c17aa61f2c10f8b626c): free 124257241 bytes of WAL
I20260812 06:19:42.268105 11690 log_reader.cc:385] T c65bf492a6314c17aa61f2c10f8b626c: removed 12 log segments from log reader
I20260812 06:19:42.268157 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000014 (ops 67-71)
I20260812 06:19:42.268186 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000015 (ops 72-76)
I20260812 06:19:42.268218 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000016 (ops 77-81)
I20260812 06:19:42.268251 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000017 (ops 82-86)
I20260812 06:19:42.268275 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000018 (ops 87-91)
I20260812 06:19:42.268306 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000019 (ops 92-96)
I20260812 06:19:42.268359 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000020 (ops 97-101)
I20260812 06:19:42.268394 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000021 (ops 102-106)
I20260812 06:19:42.268426 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000022 (ops 107-111)
I20260812 06:19:42.268458 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000023 (ops 112-116)
I20260812 06:19:42.268487 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000024 (ops 117-120)
I20260812 06:19:42.268518 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000025 (ops 121-125)
I20260812 06:19:42.291970 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: LogGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.024s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:42.292431 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c): 482 bytes on disk
I20260812 06:19:42.292923 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.293495 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=3.181125
I20260812 06:19:42.310310 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.017s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4800074,"delete_count":0,"lbm_write_time_us":6683,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:19:42.310719 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling LogGCOp(c65bf492a6314c17aa61f2c10f8b626c): free 12017940 bytes of WAL
I20260812 06:19:42.310910 11690 log_reader.cc:385] T c65bf492a6314c17aa61f2c10f8b626c: removed 1 log segments from log reader
I20260812 06:19:42.310953 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000026 (ops 126-130)
I20260812 06:19:42.313077 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: LogGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:42.313417 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:42.330937 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":3401,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:19:42.331571 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:42.542060 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.210s	user 0.129s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":128,"lbm_read_time_us":15006,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35703,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":46080,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:19:42.542584 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=18.063937
I20260812 06:19:42.592468 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.050s	user 0.032s	sys 0.017s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":21414,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:42.592984 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:42.607519 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5570,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.607981 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:42.808951 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.201s	user 0.137s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877108,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":677,"lbm_read_time_us":13737,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32736,"lbm_writes_lt_1ms":643,"mutex_wait_us":296,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:19:42.809525 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:42.867842 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.058s	user 0.029s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20436,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.868326 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:42.878207 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.878634 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:43.048007 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.169s	user 0.090s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":836,"lbm_read_time_us":11385,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26854,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:43.048626 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:43.103222 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.054s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18185,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.103868 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:43.114218 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.114761 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:43.277118 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.162s	user 0.102s	sys 0.059s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":11788,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28208,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:43.277663 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=11.118625
I20260812 06:19:43.311704 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14276,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.312196 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:43.332527 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.020s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.333092 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:43.488056 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.155s	user 0.108s	sys 0.033s 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":836,"lbm_read_time_us":9333,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23006,"lbm_writes_lt_1ms":443,"mutex_wait_us":285,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:43.488744 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:43.723711 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.235s	user 0.155s	sys 0.062s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":96796,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.726846 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:43.778956 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.051s	user 0.037s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":18604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.781076 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:44.134881 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.353s	user 0.255s	sys 0.086s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":982,"lbm_read_time_us":40664,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":59034,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":361,"threads_started":6,"update_count":2500}
I20260812 06:19:44.135353 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=14.095187
I20260812 06:19:44.187542 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.052s	user 0.020s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21316,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:44.188159 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=2.188937
I20260812 06:19:44.199720 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.200259 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:44.237752 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushMRSOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.037s	user 0.025s	sys 0.008s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":243,"dirs.run_wall_time_us":1214,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1860,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:19:44.238709 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling LogGCOp(c65bf492a6314c17aa61f2c10f8b626c): free 129320784 bytes of WAL
I20260812 06:19:44.238934 11690 log_reader.cc:385] T c65bf492a6314c17aa61f2c10f8b626c: removed 13 log segments from log reader
I20260812 06:19:44.238977 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000027 (ops 131-135)
I20260812 06:19:44.239017 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000028 (ops 136-140)
I20260812 06:19:44.239051 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000029 (ops 141-144)
I20260812 06:19:44.239115 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000030 (ops 145-149)
I20260812 06:19:44.239152 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000031 (ops 150-154)
I20260812 06:19:44.239179 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000032 (ops 155-158)
I20260812 06:19:44.239235 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000033 (ops 159-163)
I20260812 06:19:44.239271 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000034 (ops 164-168)
I20260812 06:19:44.239297 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000035 (ops 169-173)
I20260812 06:19:44.239324 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000036 (ops 174-178)
I20260812 06:19:44.239370 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000037 (ops 179-183)
I20260812 06:19:44.239414 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000038 (ops 184-188)
I20260812 06:19:44.239471 11690 log.cc:1079] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/c65bf492a6314c17aa61f2c10f8b626c/wal-000000039 (ops 189-193)
I20260812 06:19:44.266969 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: LogGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.028s	user 0.001s	sys 0.024s Metrics: {}
I20260812 06:19:44.267408 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c): 508 bytes on disk
I20260812 06:19:44.267844 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: UndoDeltaBlockGCOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:44.268456 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=6.157687
I20260812 06:19:44.301069 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.032s	user 0.011s	sys 0.016s Metrics: {"bytes_written":8205079,"delete_count":0,"lbm_write_time_us":8576,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:44.301677 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=1.000000
I20260812 06:19:44.409190 11491 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.041s	user 1.853s	sys 0.107s
I20260812 06:19:44.510411 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: MajorDeltaCompactionOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.209s	user 0.122s	sys 0.084s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":786,"lbm_read_time_us":14355,"lbm_reads_lt_1ms":761,"lbm_write_time_us":35100,"lbm_writes_lt_1ms":743,"mutex_wait_us":593,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":113,"threads_started":1,"update_count":3500}
I20260812 06:19:44.511145 11807 maintenance_manager.cc:419] P 8f4441542c29481095169430344b8365: Scheduling FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c): perf score=10.126437
I20260812 06:19:44.511925 11491 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.003s	sys 0.000s
I20260812 06:19:44.512683 11491 tablet_server.cc:179] TabletServer@127.11.56.193:0 shutting down...
I20260812 06:19:44.539816 11690 maintenance_manager.cc:643] P 8f4441542c29481095169430344b8365: FlushDeltaMemStoresOp(c65bf492a6314c17aa61f2c10f8b626c) complete. Timing: real 0.028s	user 0.019s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":11948,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:44.540446 11491 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:44.540819 11491 tablet_replica.cc:333] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365: stopping tablet replica
I20260812 06:19:44.541051 11491 raft_consensus.cc:2243] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.541266 11491 raft_consensus.cc:2272] T c65bf492a6314c17aa61f2c10f8b626c P 8f4441542c29481095169430344b8365 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.546223 11491 tablet_server.cc:196] TabletServer@127.11.56.193:0 shutdown complete.
I20260812 06:19:44.568259 11491 master.cc:562] Master@127.11.56.254:38673 shutting down...
I20260812 06:19:44.571605 11491 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.571770 11491 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.571825 11491 tablet_replica.cc:333] T 00000000000000000000000000000000 P 2710b2103e8a4703838900845dbfdcbc: stopping tablet replica
I20260812 06:19:44.584113 11491 master.cc:584] Master@127.11.56.254:38673 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5569 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:44.668679 11491 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.56.254:42097
I20260812 06:19:44.669078 11491 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:19:44.671038 11491 server_base.cc:1061] running on GCE node
W20260812 06:19:44.671198 11860 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:44.671216 11859 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:44.671237 11867 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:44.671509 11491 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.671553 11491 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:44.671567 11491 hybrid_clock.cc:648] HybridClock initialized: now 1786515584671567 us; error 0 us; skew 500 ppm
I20260812 06:19:44.672437 11491 webserver.cc:533] Webserver started at http://127.11.56.254:36683/ using document root <none> and password file <none>
I20260812 06:19:44.672605 11491 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.672657 11491 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.672717 11491 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.673101 11491 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/master-0-root/instance:
uuid: "afd546ba69574a3c8452bfdb38477bc2"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-xt4k"
I20260812 06:19:44.674557 11491 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:44.675411 11878 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.675678 11491 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:44.675752 11491 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/master-0-root
uuid: "afd546ba69574a3c8452bfdb38477bc2"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-xt4k"
I20260812 06:19:44.675815 11491 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:44.690574 11491 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.690966 11491 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.695025 11491 rpc_server.cc:307] RPC server started. Bound to: 127.11.56.254:42097
I20260812 06:19:44.699275 11983 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.56.254:42097 every 8 connection(s)
I20260812 06:19:44.699774 11985 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:44.701699 11985 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: Bootstrap starting.
I20260812 06:19:44.702540 11985 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.703554 11985 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: No bootstrap required, opened a new log
I20260812 06:19:44.703943 11985 raft_consensus.cc:359] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER }
I20260812 06:19:44.704033 11985 raft_consensus.cc:385] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.704066 11985 raft_consensus.cc:740] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: afd546ba69574a3c8452bfdb38477bc2, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.704219 11985 consensus_queue.cc:260] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [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: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER }
I20260812 06:19:44.704311 11985 raft_consensus.cc:399] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.704380 11985 raft_consensus.cc:493] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.704432 11985 raft_consensus.cc:3060] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.705255 11985 raft_consensus.cc:515] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER }
I20260812 06:19:44.705391 11985 leader_election.cc:304] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [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: afd546ba69574a3c8452bfdb38477bc2; no voters: 
I20260812 06:19:44.705587 11985 leader_election.cc:290] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.705681 11992 raft_consensus.cc:2804] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.705839 11992 raft_consensus.cc:697] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 1 LEADER]: Becoming Leader. State: Replica: afd546ba69574a3c8452bfdb38477bc2, State: Running, Role: LEADER
I20260812 06:19:44.706079 11985 sys_catalog.cc:565] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:44.706053 11992 consensus_queue.cc:237] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [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: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER }
I20260812 06:19:44.706488 11993 sys_catalog.cc:455] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "afd546ba69574a3c8452bfdb38477bc2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER } }
I20260812 06:19:44.706523 11994 sys_catalog.cc:455] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader afd546ba69574a3c8452bfdb38477bc2. Latest consensus state: current_term: 1 leader_uuid: "afd546ba69574a3c8452bfdb38477bc2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "afd546ba69574a3c8452bfdb38477bc2" member_type: VOTER } }
I20260812 06:19:44.706645 11993 sys_catalog.cc:458] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.706665 11994 sys_catalog.cc:458] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:44.707868 11491 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:44.708319 12020 catalog_manager.cc:1594] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:44.708416 12020 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:44.708492 11998 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:44.709079 11998 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:44.710852 11998 catalog_manager.cc:1383] Generated new cluster ID: 0022e81e9a1f4ad2aecf59ee5a8616cd
I20260812 06:19:44.710903 11998 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:44.728783 11998 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:44.729373 11998 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:44.736910 11998 catalog_manager.cc:6092] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: Generated new TSK 0
I20260812 06:19:44.737089 11998 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:44.740099 11491 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:44.742106 12028 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:44.742172 11491 server_base.cc:1061] running on GCE node
W20260812 06:19:44.742198 12025 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:44.742120 12022 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:44.742472 11491 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:44.742522 11491 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:44.742538 11491 hybrid_clock.cc:648] HybridClock initialized: now 1786515584742538 us; error 0 us; skew 500 ppm
I20260812 06:19:44.743337 11491 webserver.cc:533] Webserver started at http://127.11.56.193:46207/ using document root <none> and password file <none>
I20260812 06:19:44.743487 11491 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:44.743546 11491 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:44.743630 11491 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:44.743996 11491 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/instance:
uuid: "d38dee118ec24daa91fc9092adfbbb5c"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-xt4k"
I20260812 06:19:44.745460 11491 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:44.746380 12037 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.746629 11491 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:44.746701 11491 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root
uuid: "d38dee118ec24daa91fc9092adfbbb5c"
format_stamp: "Formatted at 2026-08-12 06:19:44 on dist-test-slave-xt4k"
I20260812 06:19:44.746769 11491 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:44.752753 11491 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:44.753083 11491 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:44.753351 11491 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:44.753782 11491 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:44.753819 11491 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.753861 11491 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:44.753890 11491 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:44.757969 11491 rpc_server.cc:307] RPC server started. Bound to: 127.11.56.193:42987
I20260812 06:19:44.759061 12159 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.56.193:42987 every 8 connection(s)
I20260812 06:19:44.766860 12160 heartbeater.cc:344] Connected to a master server at 127.11.56.254:42097
I20260812 06:19:44.766974 12160 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:44.767171 12160 heartbeater.cc:507] Master 127.11.56.254:42097 requested a full tablet report, sending...
I20260812 06:19:44.767784 11912 ts_manager.cc:194] Registered new tserver with Master: d38dee118ec24daa91fc9092adfbbb5c (127.11.56.193:42987)
I20260812 06:19:44.768522 11912 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45848
I20260812 06:19:44.768605 11491 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009945372s
I20260812 06:19:44.775055 11912 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45856:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:44.783046 12092 tablet_service.cc:1511] Processing CreateTablet for tablet 655152b02bf7445baf16ff8000783dd2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=363cd6e601e84746ab5a2d2ed06a8899]), partition=
I20260812 06:19:44.783310 12092 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 655152b02bf7445baf16ff8000783dd2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:44.785193 12181 tablet_bootstrap.cc:492] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Bootstrap starting.
I20260812 06:19:44.786021 12181 tablet_bootstrap.cc:654] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:44.787102 12181 tablet_bootstrap.cc:492] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: No bootstrap required, opened a new log
I20260812 06:19:44.787180 12181 ts_tablet_manager.cc:1403] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:44.787585 12181 raft_consensus.cc:359] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d38dee118ec24daa91fc9092adfbbb5c" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 42987 } }
I20260812 06:19:44.787671 12181 raft_consensus.cc:385] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:44.787706 12181 raft_consensus.cc:740] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d38dee118ec24daa91fc9092adfbbb5c, State: Initialized, Role: FOLLOWER
I20260812 06:19:44.787839 12181 consensus_queue.cc:260] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [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: "d38dee118ec24daa91fc9092adfbbb5c" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 42987 } }
I20260812 06:19:44.787922 12181 raft_consensus.cc:399] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:44.787945 12181 raft_consensus.cc:493] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:44.787986 12181 raft_consensus.cc:3060] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:44.788826 12181 raft_consensus.cc:515] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d38dee118ec24daa91fc9092adfbbb5c" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 42987 } }
I20260812 06:19:44.788964 12181 leader_election.cc:304] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [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: d38dee118ec24daa91fc9092adfbbb5c; no voters: 
I20260812 06:19:44.789153 12181 leader_election.cc:290] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:44.789247 12184 raft_consensus.cc:2804] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:44.789458 12160 heartbeater.cc:499] Master 127.11.56.254:42097 was elected leader, sending a full tablet report...
I20260812 06:19:44.789438 12181 ts_tablet_manager.cc:1434] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:44.789449 12184 raft_consensus.cc:697] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 1 LEADER]: Becoming Leader. State: Replica: d38dee118ec24daa91fc9092adfbbb5c, State: Running, Role: LEADER
I20260812 06:19:44.789695 12184 consensus_queue.cc:237] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [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: "d38dee118ec24daa91fc9092adfbbb5c" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 42987 } }
I20260812 06:19:44.790925 11912 catalog_manager.cc:5719] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c reported cstate change: term changed from 0 to 1, leader changed from <none> to d38dee118ec24daa91fc9092adfbbb5c (127.11.56.193). New cstate: current_term: 1 leader_uuid: "d38dee118ec24daa91fc9092adfbbb5c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d38dee118ec24daa91fc9092adfbbb5c" member_type: VOTER last_known_addr { host: "127.11.56.193" port: 42987 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:44.845466 11491 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.051s	user 0.017s	sys 0.006s
I20260812 06:19:45.009696 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushMRSOp(655152b02bf7445baf16ff8000783dd2): perf score=23.023690
I20260812 06:19:45.155577 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushMRSOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.146s	user 0.102s	sys 0.040s Metrics: {"bytes_written":12717734,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":817,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36153,"lbm_writes_lt_1ms":867,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":11136,"update_count":1550}
I20260812 06:19:45.156183 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling LogGCOp(655152b02bf7445baf16ff8000783dd2): free 20743880 bytes of WAL
I20260812 06:19:45.156418 12043 log_reader.cc:385] T 655152b02bf7445baf16ff8000783dd2: removed 2 log segments from log reader
I20260812 06:19:45.156464 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000001 (ops 1-6)
I20260812 06:19:45.156493 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000002 (ops 7-11)
I20260812 06:19:45.159996 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: LogGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:45.160321 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2): 20513812 bytes on disk
I20260812 06:19:45.160740 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:45.161115 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:45.174691 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4702,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:45.175087 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:45.326339 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.151s	user 0.099s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713262,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":491,"lbm_read_time_us":10749,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25101,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":298,"threads_started":5,"update_count":2000}
I20260812 06:19:45.326921 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:45.362023 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.035s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12080,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.362534 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:45.373042 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.373477 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:45.511170 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.138s	user 0.113s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":10647,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22492,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:19:45.513942 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:45.540187 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.026s	user 0.020s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11186,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.540671 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:45.550608 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3730,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.551040 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:45.686899 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.136s	user 0.107s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":901,"lbm_read_time_us":8710,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22051,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:45.687469 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:45.730960 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.043s	user 0.021s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19913,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.731467 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:45.741824 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.742280 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:45.867453 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.125s	user 0.103s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":884,"lbm_read_time_us":8187,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23934,"lbm_writes_lt_1ms":443,"mutex_wait_us":292,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:45.868268 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:45.910516 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.042s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13961,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:45.910936 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:45.920648 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:45.921108 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:46.040166 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.119s	user 0.091s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":156,"lbm_read_time_us":9177,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21848,"lbm_writes_lt_1ms":443,"mutex_wait_us":65,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:19:46.040685 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:46.091393 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.050s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14475,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.091931 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.102140 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3836,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.102577 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:46.245766 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.143s	user 0.078s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":205,"lbm_read_time_us":10505,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22381,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2000}
I20260812 06:19:46.246330 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:46.278702 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.032s	user 0.021s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":11546,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:46.279141 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushMRSOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:46.316519 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushMRSOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.037s	user 0.020s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1383,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1409,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:46.317189 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2): 447 bytes on disk
I20260812 06:19:46.317826 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":103,"lbm_reads_lt_1ms":4}
I20260812 06:19:46.318261 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=3.181125
I20260812 06:19:46.331436 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4635977,"delete_count":0,"lbm_write_time_us":4235,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:19:46.331949 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling LogGCOp(655152b02bf7445baf16ff8000783dd2): free 112239255 bytes of WAL
I20260812 06:19:46.332186 12043 log_reader.cc:385] T 655152b02bf7445baf16ff8000783dd2: removed 11 log segments from log reader
I20260812 06:19:46.332233 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000003 (ops 12-16)
I20260812 06:19:46.332274 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000004 (ops 17-21)
I20260812 06:19:46.332306 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000005 (ops 22-26)
I20260812 06:19:46.332360 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000006 (ops 27-31)
I20260812 06:19:46.332393 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000007 (ops 32-36)
I20260812 06:19:46.332425 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000008 (ops 37-41)
I20260812 06:19:46.332455 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000009 (ops 42-46)
I20260812 06:19:46.332523 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000010 (ops 47-50)
I20260812 06:19:46.332552 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000011 (ops 51-55)
I20260812 06:19:46.332577 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000012 (ops 56-60)
I20260812 06:19:46.332607 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000013 (ops 61-65)
I20260812 06:19:46.353314 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: LogGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:19:46.353820 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.381880 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.028s	user 0.005s	sys 0.017s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5887,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:46.382472 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling LogGCOp(655152b02bf7445baf16ff8000783dd2): free 12017983 bytes of WAL
I20260812 06:19:46.382710 12043 log_reader.cc:385] T 655152b02bf7445baf16ff8000783dd2: removed 1 log segments from log reader
I20260812 06:19:46.382761 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000014 (ops 66-70)
I20260812 06:19:46.384789 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: LogGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:46.385105 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.394397 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3346,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.394857 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:46.585958 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.191s	user 0.127s	sys 0.064s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":802,"lbm_read_time_us":13427,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31358,"lbm_writes_lt_1ms":643,"mutex_wait_us":328,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":18688,"thread_start_us":96,"threads_started":1,"update_count":3000}
I20260812 06:19:46.586493 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=14.095187
I20260812 06:19:46.637665 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.051s	user 0.022s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":16847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:46.638199 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.654151 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5976,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.654687 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:46.818826 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.164s	user 0.114s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":512,"lbm_read_time_us":12430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25801,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2500}
I20260812 06:19:46.819486 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=11.118625
I20260812 06:19:46.862036 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.042s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16121,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:46.862514 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.877638 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.015s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:46.878178 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:46.900539 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.022s	user 0.011s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4858,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:46.901113 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.081185 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.180s	user 0.119s	sys 0.056s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815795,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":714,"lbm_read_time_us":14121,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27824,"lbm_writes_lt_1ms":543,"mutex_wait_us":334,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:47.081801 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=11.118625
I20260812 06:19:47.118144 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.036s	user 0.030s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15284,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:47.118937 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:47.133576 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.014s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3679,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.134086 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.260731 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.126s	user 0.096s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1917,"lbm_read_time_us":9106,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23241,"lbm_writes_lt_1ms":443,"mutex_wait_us":1371,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2000}
I20260812 06:19:47.261283 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:47.299072 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.038s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14978,"lbm_writes_lt_1ms":303,"mutex_wait_us":2,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.299615 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:47.314674 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5456,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.315249 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.436599 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.121s	user 0.079s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":8922,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21959,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:19:47.437192 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:47.468097 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.031s	user 0.022s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12642,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.468701 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.569267 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.100s	user 0.087s	sys 0.012s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":448,"lbm_read_time_us":7317,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17366,"lbm_writes_lt_1ms":343,"mutex_wait_us":38,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":1500}
I20260812 06:19:47.569837 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:47.612221 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.042s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14372,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.612735 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:47.622735 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3676,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.623524 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.750176 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.126s	user 0.094s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":222,"lbm_read_time_us":8258,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23050,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14720,"update_count":2000}
I20260812 06:19:47.750689 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:47.793593 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.043s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17113,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:47.794082 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:47.804301 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3844,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:47.804939 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushMRSOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:47.832731 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushMRSOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.028s	user 0.021s	sys 0.006s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1404,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1493,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:47.833425 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling LogGCOp(655152b02bf7445baf16ff8000783dd2): free 121006444 bytes of WAL
I20260812 06:19:47.833678 12043 log_reader.cc:385] T 655152b02bf7445baf16ff8000783dd2: removed 12 log segments from log reader
I20260812 06:19:47.833727 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000015 (ops 71-75)
I20260812 06:19:47.833765 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000016 (ops 76-80)
I20260812 06:19:47.833799 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000017 (ops 81-85)
I20260812 06:19:47.833832 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000018 (ops 86-90)
I20260812 06:19:47.833868 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000019 (ops 91-95)
I20260812 06:19:47.833899 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000020 (ops 96-100)
I20260812 06:19:47.833926 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000021 (ops 101-105)
I20260812 06:19:47.833958 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000022 (ops 106-110)
I20260812 06:19:47.833990 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000023 (ops 111-115)
I20260812 06:19:47.834022 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000024 (ops 116-120)
I20260812 06:19:47.834052 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000025 (ops 121-124)
I20260812 06:19:47.834084 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000026 (ops 125-129)
I20260812 06:19:47.856153 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: LogGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.023s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:47.856612 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=3.181125
I20260812 06:19:47.874954 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6644,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:47.875355 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2): 485 bytes on disk
I20260812 06:19:47.875717 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:47.876178 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:47.884933 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3163,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:47.885300 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.044551 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.159s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1117,"lbm_read_time_us":10731,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30011,"lbm_writes_lt_1ms":643,"mutex_wait_us":505,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3456,"thread_start_us":94,"threads_started":1,"update_count":3000}
I20260812 06:19:48.045117 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=14.095187
I20260812 06:19:48.094982 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.050s	user 0.029s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20517,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:48.095472 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:48.106065 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s 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:19:48.106660 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.251555 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.145s	user 0.099s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":9920,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25885,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32640,"update_count":2500}
I20260812 06:19:48.252292 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=11.118625
I20260812 06:19:48.282783 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.030s	user 0.019s	sys 0.008s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":12147,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:48.283284 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:48.294819 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3596,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:48.295339 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.421039 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.126s	user 0.101s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713266,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":42,"lbm_read_time_us":8101,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22333,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:48.421645 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:48.463460 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.042s	user 0.018s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":12622,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.463940 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:48.473912 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3618,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.474432 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.592576 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.118s	user 0.092s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1229,"lbm_read_time_us":9155,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20681,"lbm_writes_lt_1ms":443,"mutex_wait_us":420,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:48.593299 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:48.636545 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":13690,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.637169 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:48.647996 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4099,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.648618 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.804478 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.156s	user 0.090s	sys 0.064s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":374,"lbm_read_time_us":10097,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26447,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2000}
I20260812 06:19:48.805208 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:48.839094 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.033s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14515,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.839589 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:48.941766 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.102s	user 0.070s	sys 0.031s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":960,"lbm_read_time_us":6838,"lbm_reads_lt_1ms":363,"lbm_write_time_us":17859,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:48.942318 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:48.986917 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.044s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:48.987498 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:48.997619 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:48.998198 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:49.123540 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.125s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":216,"lbm_read_time_us":10068,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22596,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":2000}
I20260812 06:19:49.124115 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=10.126437
I20260812 06:19:49.172034 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.048s	user 0.011s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13148,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:49.172662 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:49.182904 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.183346 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushMRSOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:49.211090 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushMRSOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":154,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1288,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1434,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:49.211858 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2): 473 bytes on disk
I20260812 06:19:49.212539 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: UndoDeltaBlockGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:49.213073 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:49.349431 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.136s	user 0.108s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":611,"lbm_read_time_us":10537,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20290,"lbm_writes_lt_1ms":443,"mutex_wait_us":288,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:19:49.350155 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling LogGCOp(655152b02bf7445baf16ff8000783dd2): free 124257508 bytes of WAL
I20260812 06:19:49.350409 12043 log_reader.cc:385] T 655152b02bf7445baf16ff8000783dd2: removed 12 log segments from log reader
I20260812 06:19:49.350466 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000027 (ops 130-134)
I20260812 06:19:49.350561 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000028 (ops 135-139)
I20260812 06:19:49.350613 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000029 (ops 140-144)
I20260812 06:19:49.350683 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000030 (ops 145-149)
I20260812 06:19:49.350728 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000031 (ops 150-154)
I20260812 06:19:49.350766 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000032 (ops 155-159)
I20260812 06:19:49.350800 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000033 (ops 160-164)
I20260812 06:19:49.350834 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000034 (ops 165-168)
I20260812 06:19:49.350867 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000035 (ops 169-173)
I20260812 06:19:49.350901 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000036 (ops 174-178)
I20260812 06:19:49.350970 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000037 (ops 179-183)
I20260812 06:19:49.351013 12043 log.cc:1079] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: Deleting log segment in path: /tmp/dist-test-taskc5xbR6/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515579078261-11491-0/minicluster-data/ts-0-root/wals/655152b02bf7445baf16ff8000783dd2/wal-000000038 (ops 184-188)
I20260812 06:19:49.374928 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: LogGCOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:19:49.375366 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=14.095187
I20260812 06:19:49.415032 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.039s	user 0.016s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17489,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:49.415565 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2): perf score=2.188937
I20260812 06:19:49.428454 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: FlushDeltaMemStoresOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:49.428951 12161 maintenance_manager.cc:419] P d38dee118ec24daa91fc9092adfbbb5c: Scheduling MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2): perf score=1.000000
I20260812 06:19:49.446280 11491 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.601s	user 1.692s	sys 0.133s
I20260812 06:19:49.497191 11491 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.050s	user 0.002s	sys 0.000s
I20260812 06:19:49.497660 11491 tablet_server.cc:179] TabletServer@127.11.56.193:0 shutting down...
I20260812 06:19:49.554291 12043 maintenance_manager.cc:643] P d38dee118ec24daa91fc9092adfbbb5c: MajorDeltaCompactionOp(655152b02bf7445baf16ff8000783dd2) complete. Timing: real 0.125s	user 0.088s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":350,"lbm_read_time_us":9676,"lbm_reads_lt_1ms":560,"lbm_write_time_us":23420,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:19:49.554960 11491 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:49.555250 11491 tablet_replica.cc:333] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c: stopping tablet replica
I20260812 06:19:49.555370 11491 raft_consensus.cc:2243] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.555546 11491 raft_consensus.cc:2272] T 655152b02bf7445baf16ff8000783dd2 P d38dee118ec24daa91fc9092adfbbb5c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.560391 11491 tablet_server.cc:196] TabletServer@127.11.56.193:0 shutdown complete.
I20260812 06:19:49.599426 11491 master.cc:562] Master@127.11.56.254:42097 shutting down...
I20260812 06:19:49.602444 11491 raft_consensus.cc:2243] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:49.602789 11491 raft_consensus.cc:2272] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:49.602876 11491 tablet_replica.cc:333] T 00000000000000000000000000000000 P afd546ba69574a3c8452bfdb38477bc2: stopping tablet replica
I20260812 06:19:49.615477 11491 master.cc:584] Master@127.11.56.254:42097 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5030 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10600 ms total)

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