[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:59.354714 30034 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.84.190:40537
I20260812 06:17:59.355829 30034 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:59.356511 30034 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.364701 30041 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.364789 30044 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.365182 30042 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.365352 30034 server_base.cc:1061] running on GCE node
I20260812 06:17:59.365882 30034 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.365975 30034 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.366003 30034 hybrid_clock.cc:648] HybridClock initialized: now 1786515479366002 us; error 0 us; skew 500 ppm
I20260812 06:17:59.368134 30034 webserver.cc:533] Webserver started at http://127.29.84.190:46475/ using document root <none> and password file <none>
I20260812 06:17:59.368710 30034 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.368786 30034 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.369000 30034 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.370915 30034 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/master-0-root/instance:
uuid: "149508e8a16248469266b66250985880"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-csg5"
I20260812 06:17:59.374927 30034 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.004s	sys 0.000s
I20260812 06:17:59.377388 30049 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.378822 30034 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:17:59.378994 30034 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/master-0-root
uuid: "149508e8a16248469266b66250985880"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-csg5"
I20260812 06:17:59.379138 30034 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.395076 30034 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.395875 30034 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:59.396100 30034 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.405274 30034 rpc_server.cc:307] RPC server started. Bound to: 127.29.84.190:40537
I20260812 06:17:59.405400 30112 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.84.190:40537 every 8 connection(s)
I20260812 06:17:59.407994 30113 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.413911 30113 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: Bootstrap starting.
I20260812 06:17:59.416570 30113 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.417680 30113 log.cc:826] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:59.419762 30113 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: No bootstrap required, opened a new log
I20260812 06:17:59.422995 30113 raft_consensus.cc:359] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "149508e8a16248469266b66250985880" member_type: VOTER }
I20260812 06:17:59.423214 30113 raft_consensus.cc:385] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.423267 30113 raft_consensus.cc:740] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 149508e8a16248469266b66250985880, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.423926 30113 consensus_queue.cc:260] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [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: "149508e8a16248469266b66250985880" member_type: VOTER }
I20260812 06:17:59.424106 30113 raft_consensus.cc:399] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.424188 30113 raft_consensus.cc:493] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.424333 30113 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.425304 30113 raft_consensus.cc:515] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "149508e8a16248469266b66250985880" member_type: VOTER }
I20260812 06:17:59.425825 30113 leader_election.cc:304] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [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: 149508e8a16248469266b66250985880; no voters: 
I20260812 06:17:59.426204 30113 leader_election.cc:290] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.426537 30117 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.426887 30117 raft_consensus.cc:697] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 1 LEADER]: Becoming Leader. State: Replica: 149508e8a16248469266b66250985880, State: Running, Role: LEADER
I20260812 06:17:59.427397 30113 sys_catalog.cc:565] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:59.427441 30117 consensus_queue.cc:237] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [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: "149508e8a16248469266b66250985880" member_type: VOTER }
I20260812 06:17:59.429885 30120 sys_catalog.cc:455] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "149508e8a16248469266b66250985880" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "149508e8a16248469266b66250985880" member_type: VOTER } }
I20260812 06:17:59.429847 30121 sys_catalog.cc:455] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 149508e8a16248469266b66250985880. Latest consensus state: current_term: 1 leader_uuid: "149508e8a16248469266b66250985880" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "149508e8a16248469266b66250985880" member_type: VOTER } }
I20260812 06:17:59.430048 30120 sys_catalog.cc:458] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.430086 30121 sys_catalog.cc:458] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:59.429877 30034 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:59.432327 30135 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:59.432426 30135 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:59.432550 30136 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:59.433431 30136 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:59.438869 30136 catalog_manager.cc:1383] Generated new cluster ID: f43ddf245911483c9a5f1abbd417d459
I20260812 06:17:59.438972 30136 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:59.447247 30136 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:59.448259 30136 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:59.459733 30136 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: Generated new TSK 0
I20260812 06:17:59.460562 30136 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:59.463174 30034 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:59.466341 30140 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.466506 30141 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:59.466564 30143 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:59.466866 30034 server_base.cc:1061] running on GCE node
I20260812 06:17:59.467043 30034 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:59.467092 30034 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:59.467115 30034 hybrid_clock.cc:648] HybridClock initialized: now 1786515479467115 us; error 0 us; skew 500 ppm
I20260812 06:17:59.468156 30034 webserver.cc:533] Webserver started at http://127.29.84.129:43397/ using document root <none> and password file <none>
I20260812 06:17:59.468339 30034 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:59.468401 30034 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:59.468480 30034 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:59.469003 30034 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/instance:
uuid: "227b30311ae443988037fe5f0726f595"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-csg5"
I20260812 06:17:59.471045 30034 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:17:59.472416 30148 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.472805 30034 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:59.472877 30034 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root
uuid: "227b30311ae443988037fe5f0726f595"
format_stamp: "Formatted at 2026-08-12 06:17:59 on dist-test-slave-csg5"
I20260812 06:17:59.472976 30034 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:59.479867 30034 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:59.480371 30034 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:59.480877 30034 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:59.481822 30034 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:59.481899 30034 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.481977 30034 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:59.482028 30034 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:59.489542 30034 rpc_server.cc:307] RPC server started. Bound to: 127.29.84.129:40157
I20260812 06:17:59.489566 30215 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.84.129:40157 every 8 connection(s)
I20260812 06:17:59.500617 30216 heartbeater.cc:344] Connected to a master server at 127.29.84.190:40537
I20260812 06:17:59.500905 30216 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:59.501390 30216 heartbeater.cc:507] Master 127.29.84.190:40537 requested a full tablet report, sending...
I20260812 06:17:59.502933 30069 ts_manager.cc:194] Registered new tserver with Master: 227b30311ae443988037fe5f0726f595 (127.29.84.129:40157)
I20260812 06:17:59.503798 30034 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013538069s
I20260812 06:17:59.504942 30069 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49504
I20260812 06:17:59.514910 30069 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49510:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:59.530788 30180 tablet_service.cc:1511] Processing CreateTablet for tablet 99c66c66b4e94d94bad140a7f8ac74a5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=3d282a9a62a84a86bf87a0f7c86eed17]), partition=
I20260812 06:17:59.531302 30180 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 99c66c66b4e94d94bad140a7f8ac74a5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:59.533875 30229 tablet_bootstrap.cc:492] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Bootstrap starting.
I20260812 06:17:59.535125 30229 tablet_bootstrap.cc:654] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:59.536520 30229 tablet_bootstrap.cc:492] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: No bootstrap required, opened a new log
I20260812 06:17:59.536665 30229 ts_tablet_manager.cc:1403] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:59.537124 30229 raft_consensus.cc:359] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "227b30311ae443988037fe5f0726f595" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 40157 } }
I20260812 06:17:59.537266 30229 raft_consensus.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:59.537312 30229 raft_consensus.cc:740] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 227b30311ae443988037fe5f0726f595, State: Initialized, Role: FOLLOWER
I20260812 06:17:59.537503 30229 consensus_queue.cc:260] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [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: "227b30311ae443988037fe5f0726f595" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 40157 } }
I20260812 06:17:59.537727 30229 raft_consensus.cc:399] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:59.537801 30229 raft_consensus.cc:493] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:59.537870 30229 raft_consensus.cc:3060] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:59.538878 30229 raft_consensus.cc:515] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "227b30311ae443988037fe5f0726f595" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 40157 } }
I20260812 06:17:59.539055 30229 leader_election.cc:304] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [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: 227b30311ae443988037fe5f0726f595; no voters: 
I20260812 06:17:59.539265 30229 leader_election.cc:290] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:59.539403 30232 raft_consensus.cc:2804] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:59.539642 30229 ts_tablet_manager.cc:1434] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:17:59.539687 30232 raft_consensus.cc:697] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 1 LEADER]: Becoming Leader. State: Replica: 227b30311ae443988037fe5f0726f595, State: Running, Role: LEADER
I20260812 06:17:59.539875 30232 consensus_queue.cc:237] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [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: "227b30311ae443988037fe5f0726f595" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 40157 } }
I20260812 06:17:59.540405 30216 heartbeater.cc:499] Master 127.29.84.190:40537 was elected leader, sending a full tablet report...
I20260812 06:17:59.543248 30069 catalog_manager.cc:5719] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 reported cstate change: term changed from 0 to 1, leader changed from <none> to 227b30311ae443988037fe5f0726f595 (127.29.84.129). New cstate: current_term: 1 leader_uuid: "227b30311ae443988037fe5f0726f595" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "227b30311ae443988037fe5f0726f595" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 40157 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:59.615767 30034 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.066s	user 0.017s	sys 0.012s
I20260812 06:17:59.740835 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=15.086190
I20260812 06:17:59.915813 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.174s	user 0.130s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":238,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":1230,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43098,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":149,"threads_started":1,"update_count":1500}
I20260812 06:17:59.917140 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 11976772 bytes of WAL
I20260812 06:17:59.917464 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 1 log segments from log reader
I20260812 06:17:59.917531 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000001 (ops 1-6)
I20260812 06:17:59.920750 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:59.921172 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:17:59.938970 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.018s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5702,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:59.939564 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:00.096446 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.157s	user 0.120s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1352,"lbm_read_time_us":8683,"lbm_reads_lt_1ms":464,"lbm_write_time_us":30713,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12928,"thread_start_us":352,"threads_started":5,"update_count":2000}
I20260812 06:18:00.097294 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5): 12308958 bytes on disk
I20260812 06:18:00.097843 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:18:00.098263 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:00.144477 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.046s	user 0.039s	sys 0.003s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19174,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.145184 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:00.158305 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.158972 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:00.306903 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.148s	user 0.134s	sys 0.009s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1473,"lbm_read_time_us":11196,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27012,"lbm_writes_lt_1ms":443,"mutex_wait_us":1164,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:00.307523 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:00.354383 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.047s	user 0.028s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19765,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.354991 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:00.371901 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6376,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.372622 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:00.510445 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.138s	user 0.105s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":342,"lbm_read_time_us":8975,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26517,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:18:00.511166 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:00.557919 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.047s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15597,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.558832 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:00.579263 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.020s	user 0.015s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.580015 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:00.733657 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.153s	user 0.109s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":786,"lbm_read_time_us":10933,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25898,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":199296,"update_count":2000}
I20260812 06:18:00.734417 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:00.780599 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.046s	user 0.024s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19356,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.781172 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:00.792138 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4092,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.792661 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:00.920871 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.128s	user 0.109s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":943,"lbm_read_time_us":8493,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23801,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:18:00.921644 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:00.963828 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.042s	user 0.027s	sys 0.013s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17352,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:00.964422 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:00.977207 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:00.977923 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:01.099455 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.121s	user 0.093s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":7970,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23486,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.100039 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:01.144699 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.044s	user 0.025s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17712,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:01.145285 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:01.156174 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.156708 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:01.189443 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.033s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1616,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:01.190318 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 112692305 bytes of WAL
I20260812 06:18:01.190583 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 11 log segments from log reader
I20260812 06:18:01.190651 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000002 (ops 7-11)
I20260812 06:18:01.190737 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000003 (ops 12-16)
I20260812 06:18:01.190802 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000004 (ops 17-21)
I20260812 06:18:01.190851 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000005 (ops 22-26)
I20260812 06:18:01.190892 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000006 (ops 27-31)
I20260812 06:18:01.190937 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000007 (ops 32-36)
I20260812 06:18:01.190979 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000008 (ops 37-41)
I20260812 06:18:01.191023 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000009 (ops 42-46)
I20260812 06:18:01.191064 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000010 (ops 47-51)
I20260812 06:18:01.191107 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000011 (ops 52-56)
I20260812 06:18:01.191149 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000012 (ops 57-61)
I20260812 06:18:01.217021 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.026s	user 0.002s	sys 0.022s Metrics: {}
I20260812 06:18:01.217664 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5): 448 bytes on disk
I20260812 06:18:01.218449 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":131,"lbm_reads_lt_1ms":4}
I20260812 06:18:01.219190 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=3.181125
I20260812 06:18:01.244096 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.025s	user 0.019s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":8063,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:01.244638 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 12017983 bytes of WAL
I20260812 06:18:01.244897 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 1 log segments from log reader
I20260812 06:18:01.244957 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000013 (ops 62-66)
I20260812 06:18:01.247903 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:01.248505 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:01.260721 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4120,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:01.261492 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:01.446992 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.185s	user 0.136s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836363,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":632,"lbm_read_time_us":11408,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34241,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:01.447713 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:01.499331 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.051s	user 0.034s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22379,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.499845 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:01.515847 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5436,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.516369 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:01.687619 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.171s	user 0.121s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":301,"lbm_read_time_us":8850,"lbm_reads_lt_1ms":568,"lbm_write_time_us":32857,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25728,"update_count":2500}
I20260812 06:18:01.688412 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:01.749826 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.061s	user 0.018s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:01.750409 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:01.762315 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:01.762889 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:01.956017 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.193s	user 0.123s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":404,"lbm_read_time_us":12549,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31764,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:01.956627 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:02.043411 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.087s	user 0.043s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":53245,"lbm_writes_10-100_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.044031 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:02.057451 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4411,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.058125 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:02.237677 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.179s	user 0.118s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":769,"lbm_read_time_us":10769,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33040,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:18:02.238567 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:02.309187 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.070s	user 0.026s	sys 0.039s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26933,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.309876 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:02.324671 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5540,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.325273 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:02.527932 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.202s	user 0.151s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733724,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1897,"lbm_read_time_us":17530,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31307,"lbm_writes_lt_1ms":543,"mutex_wait_us":396,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22912,"update_count":2500}
I20260812 06:18:02.528597 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=11.118625
I20260812 06:18:02.565372 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.037s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16290,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:02.566265 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:02.590406 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.024s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.591254 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:02.760437 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.169s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631304,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":303,"lbm_read_time_us":10059,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25647,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:18:02.761260 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:02.811547 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.050s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19241,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:02.812077 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:02.823503 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:02.824327 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:02.857378 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":167,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1849,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2218,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:02.858320 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 117302571 bytes of WAL
I20260812 06:18:02.858615 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 12 log segments from log reader
I20260812 06:18:02.858724 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000014 (ops 67-71)
I20260812 06:18:02.858794 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000015 (ops 72-76)
I20260812 06:18:02.858873 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000016 (ops 77-81)
I20260812 06:18:02.858920 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000017 (ops 82-86)
I20260812 06:18:02.858987 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000018 (ops 87-90)
I20260812 06:18:02.859035 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000019 (ops 91-95)
I20260812 06:18:02.859081 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000020 (ops 96-100)
I20260812 06:18:02.859133 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000021 (ops 101-105)
I20260812 06:18:02.859189 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000022 (ops 106-110)
I20260812 06:18:02.859237 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000023 (ops 111-114)
I20260812 06:18:02.859285 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000024 (ops 115-119)
I20260812 06:18:02.859328 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000025 (ops 120-124)
I20260812 06:18:02.887508 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.029s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:18:02.888190 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5): 482 bytes on disk
I20260812 06:18:02.888746 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: UndoDeltaBlockGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:02.889400 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=3.181125
I20260812 06:18:02.912237 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.023s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5511,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:02.912909 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 11564877 bytes of WAL
I20260812 06:18:02.913162 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 1 log segments from log reader
I20260812 06:18:02.913226 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000026 (ops 125-128)
I20260812 06:18:02.915853 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:02.916278 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:02.927826 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.001s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:02.928364 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:03.159276 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.231s	user 0.134s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2046,"lbm_read_time_us":16699,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38171,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":37120,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:18:03.160073 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:03.217908 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.058s	user 0.048s	sys 0.001s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:03.218709 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:03.235090 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.235867 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:03.420045 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.184s	user 0.120s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733725,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":704,"lbm_read_time_us":12443,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31198,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2500}
I20260812 06:18:03.421110 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:03.469970 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.049s	user 0.017s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":24492,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.471189 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:03.500759 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.029s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.501550 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:03.670912 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.169s	user 0.136s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1996,"lbm_read_time_us":10303,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31081,"lbm_writes_lt_1ms":443,"mutex_wait_us":1299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12288,"update_count":2000}
I20260812 06:18:03.672266 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=11.118625
I20260812 06:18:03.713061 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.040s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17594,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:03.713774 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:03.730110 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6205,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:03.730610 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:03.864303 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.133s	user 0.117s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":258,"lbm_read_time_us":7902,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24908,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:18:03.864961 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:03.905375 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.040s	user 0.025s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17040,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:03.906035 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:03.923260 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6733,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:03.924095 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.065627 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.141s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":480,"lbm_read_time_us":7823,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29674,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:18:04.066205 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:04.124832 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.058s	user 0.016s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16948,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.125500 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.136818 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.137363 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.300442 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.163s	user 0.126s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":913,"lbm_read_time_us":10927,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26531,"lbm_writes_lt_1ms":443,"mutex_wait_us":388,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2000}
I20260812 06:18:04.301280 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:04.353775 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.052s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19660,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.354527 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.365847 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.366500 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.503438 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.137s	user 0.120s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":765,"lbm_read_time_us":9609,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27088,"lbm_writes_lt_1ms":443,"mutex_wait_us":305,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:04.504585 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=10.126437
I20260812 06:18:04.548839 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.044s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17772,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:04.549391 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.561143 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4001,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.561791 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.594255 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushMRSOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":261,"dirs.run_wall_time_us":1809,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1757,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:04.595191 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5): free 121006640 bytes of WAL
I20260812 06:18:04.595503 30154 log_reader.cc:385] T 99c66c66b4e94d94bad140a7f8ac74a5: removed 12 log segments from log reader
I20260812 06:18:04.595567 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000027 (ops 129-133)
I20260812 06:18:04.595608 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000028 (ops 134-138)
I20260812 06:18:04.595633 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000029 (ops 139-143)
I20260812 06:18:04.595655 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000030 (ops 144-148)
I20260812 06:18:04.595676 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000031 (ops 149-153)
I20260812 06:18:04.595705 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000032 (ops 154-158)
I20260812 06:18:04.595738 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000033 (ops 159-163)
I20260812 06:18:04.595763 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000034 (ops 164-168)
I20260812 06:18:04.595793 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000035 (ops 169-173)
I20260812 06:18:04.595824 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000036 (ops 174-178)
I20260812 06:18:04.595849 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000037 (ops 179-182)
I20260812 06:18:04.595875 30154 log.cc:1079] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/99c66c66b4e94d94bad140a7f8ac74a5/wal-000000038 (ops 183-187)
I20260812 06:18:04.629830 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: LogGCOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.034s	user 0.005s	sys 0.029s Metrics: {}
I20260812 06:18:04.630332 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.645558 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.646097 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.657187 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:04.657850 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.854163 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.196s	user 0.153s	sys 0.039s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836374,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":679,"lbm_read_time_us":12379,"lbm_reads_lt_1ms":674,"lbm_write_time_us":43944,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":108,"threads_started":1,"update_count":3000}
I20260812 06:18:04.855063 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=14.095187
I20260812 06:18:04.905342 30034 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.289s	user 1.973s	sys 0.166s
I20260812 06:18:04.908885 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.054s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21450,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:04.909382 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=2.188937
I20260812 06:18:04.919673 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: FlushDeltaMemStoresOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":500}
I20260812 06:18:04.920167 30217 maintenance_manager.cc:419] P 227b30311ae443988037fe5f0726f595: Scheduling MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5): perf score=1.000000
I20260812 06:18:04.954310 30034 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.048s	user 0.002s	sys 0.000s
I20260812 06:18:04.955214 30034 tablet_server.cc:179] TabletServer@127.29.84.129:0 shutting down...
I20260812 06:18:05.037853 30154 maintenance_manager.cc:643] P 227b30311ae443988037fe5f0726f595: MajorDeltaCompactionOp(99c66c66b4e94d94bad140a7f8ac74a5) complete. Timing: real 0.117s	user 0.086s	sys 0.030s Metrics: {"cfile_cache_hit":358,"cfile_cache_hit_bytes":14646294,"cfile_cache_miss":174,"cfile_cache_miss_bytes":10087429,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1118,"lbm_read_time_us":3805,"lbm_reads_lt_1ms":206,"lbm_write_time_us":26836,"lbm_writes_lt_1ms":543,"mutex_wait_us":356,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":65024,"update_count":2500}
I20260812 06:18:05.038940 30034 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:05.039345 30034 tablet_replica.cc:333] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595: stopping tablet replica
I20260812 06:18:05.039608 30034 raft_consensus.cc:2243] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.039877 30034 raft_consensus.cc:2272] T 99c66c66b4e94d94bad140a7f8ac74a5 P 227b30311ae443988037fe5f0726f595 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.056815 30034 tablet_server.cc:196] TabletServer@127.29.84.129:0 shutdown complete.
I20260812 06:18:05.085438 30034 master.cc:562] Master@127.29.84.190:40537 shutting down...
I20260812 06:18:05.090255 30034 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:05.090500 30034 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:05.090610 30034 tablet_replica.cc:333] T 00000000000000000000000000000000 P 149508e8a16248469266b66250985880: stopping tablet replica
I20260812 06:18:05.103605 30034 master.cc:584] Master@127.29.84.190:40537 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5836 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:05.200320 30034 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.29.84.190:45879
I20260812 06:18:05.200789 30034 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.204046 30250 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:05.204089 30034 server_base.cc:1061] running on GCE node
W20260812 06:18:05.204070 30254 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:18:05.204046 30251 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:18:05.204919 30034 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.204993 30034 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:05.205017 30034 hybrid_clock.cc:648] HybridClock initialized: now 1786515485205016 us; error 0 us; skew 500 ppm
I20260812 06:18:05.206059 30034 webserver.cc:533] Webserver started at http://127.29.84.190:36367/ using document root <none> and password file <none>
I20260812 06:18:05.206262 30034 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.206336 30034 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.206431 30034 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.206945 30034 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/master-0-root/instance:
uuid: "e2c1b368f5824b54a4be2a534ff096d9"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-csg5"
I20260812 06:18:05.208604 30034 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:05.209805 30260 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.210343 30034 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:05.210462 30034 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/master-0-root
uuid: "e2c1b368f5824b54a4be2a534ff096d9"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-csg5"
I20260812 06:18:05.210561 30034 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:05.224963 30034 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.225629 30034 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.231101 30034 rpc_server.cc:307] RPC server started. Bound to: 127.29.84.190:45879
I20260812 06:18:05.233270 30315 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.84.190:45879 every 8 connection(s)
I20260812 06:18:05.233357 30316 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:05.238193 30316 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9: Bootstrap starting.
I20260812 06:18:05.239140 30316 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.240415 30316 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9: No bootstrap required, opened a new log
I20260812 06:18:05.240881 30316 raft_consensus.cc:359] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER }
I20260812 06:18:05.241000 30316 raft_consensus.cc:385] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.241055 30316 raft_consensus.cc:740] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e2c1b368f5824b54a4be2a534ff096d9, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.241226 30316 consensus_queue.cc:260] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [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: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER }
I20260812 06:18:05.241334 30316 raft_consensus.cc:399] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.241385 30316 raft_consensus.cc:493] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.241456 30316 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.242262 30316 raft_consensus.cc:515] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER }
I20260812 06:18:05.242440 30316 leader_election.cc:304] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [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: e2c1b368f5824b54a4be2a534ff096d9; no voters: 
I20260812 06:18:05.242717 30316 leader_election.cc:290] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.242902 30319 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.243188 30319 raft_consensus.cc:697] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 1 LEADER]: Becoming Leader. State: Replica: e2c1b368f5824b54a4be2a534ff096d9, State: Running, Role: LEADER
I20260812 06:18:05.243283 30316 sys_catalog.cc:565] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:05.243374 30319 consensus_queue.cc:237] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [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: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER }
I20260812 06:18:05.243924 30320 sys_catalog.cc:455] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e2c1b368f5824b54a4be2a534ff096d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER } }
I20260812 06:18:05.243949 30321 sys_catalog.cc:455] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e2c1b368f5824b54a4be2a534ff096d9. Latest consensus state: current_term: 1 leader_uuid: "e2c1b368f5824b54a4be2a534ff096d9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e2c1b368f5824b54a4be2a534ff096d9" member_type: VOTER } }
I20260812 06:18:05.244057 30320 sys_catalog.cc:458] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.244072 30321 sys_catalog.cc:458] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:05.244427 30326 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:05.245368 30326 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:05.245586 30034 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:05.248167 30326 catalog_manager.cc:1383] Generated new cluster ID: 34206b2983ce42c29ec90fcf1b15a694
I20260812 06:18:05.248250 30326 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:05.262763 30326 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:05.263589 30326 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:05.273552 30326 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9: Generated new TSK 0
I20260812 06:18:05.273845 30326 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:05.278137 30034 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:05.280666 30342 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:18:05.280834 30339 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:05.280704 30340 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:18:05.280937 30034 server_base.cc:1061] running on GCE node
I20260812 06:18:05.281337 30034 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:05.281392 30034 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:05.281409 30034 hybrid_clock.cc:648] HybridClock initialized: now 1786515485281409 us; error 0 us; skew 500 ppm
I20260812 06:18:05.282406 30034 webserver.cc:533] Webserver started at http://127.29.84.129:39879/ using document root <none> and password file <none>
I20260812 06:18:05.282605 30034 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:05.282713 30034 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:05.282827 30034 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:05.283285 30034 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/instance:
uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-csg5"
I20260812 06:18:05.285019 30034 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:05.286443 30347 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.286921 30034 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:05.287026 30034 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root
uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f"
format_stamp: "Formatted at 2026-08-12 06:18:05 on dist-test-slave-csg5"
I20260812 06:18:05.287133 30034 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:05.296885 30034 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:05.297362 30034 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:05.297724 30034 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:05.298237 30034 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:05.298301 30034 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.298367 30034 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:05.298418 30034 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:05.303380 30034 rpc_server.cc:307] RPC server started. Bound to: 127.29.84.129:38671
I20260812 06:18:05.304142 30426 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.29.84.129:38671 every 8 connection(s)
I20260812 06:18:05.315003 30427 heartbeater.cc:344] Connected to a master server at 127.29.84.190:45879
I20260812 06:18:05.315146 30427 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:05.315485 30427 heartbeater.cc:507] Master 127.29.84.190:45879 requested a full tablet report, sending...
I20260812 06:18:05.316411 30279 ts_manager.cc:194] Registered new tserver with Master: fbdc67febde1435bbbaeb1cc8ec5f89f (127.29.84.129:38671)
I20260812 06:18:05.316694 30034 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01244702s
I20260812 06:18:05.317561 30279 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58574
I20260812 06:18:05.326071 30279 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58578:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:05.339087 30381 tablet_service.cc:1511] Processing CreateTablet for tablet ef9fa577bff744d0aed49a154ae78820 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1cccc2dba0884e48b489425e5194a62b]), partition=
I20260812 06:18:05.339476 30381 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ef9fa577bff744d0aed49a154ae78820. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:05.341918 30441 tablet_bootstrap.cc:492] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Bootstrap starting.
I20260812 06:18:05.343066 30441 tablet_bootstrap.cc:654] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:05.344767 30441 tablet_bootstrap.cc:492] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: No bootstrap required, opened a new log
I20260812 06:18:05.344899 30441 ts_tablet_manager.cc:1403] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:05.345427 30441 raft_consensus.cc:359] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 38671 } }
I20260812 06:18:05.345546 30441 raft_consensus.cc:385] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:05.345592 30441 raft_consensus.cc:740] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: fbdc67febde1435bbbaeb1cc8ec5f89f, State: Initialized, Role: FOLLOWER
I20260812 06:18:05.345745 30441 consensus_queue.cc:260] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [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: "fbdc67febde1435bbbaeb1cc8ec5f89f" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 38671 } }
I20260812 06:18:05.345844 30441 raft_consensus.cc:399] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:05.345887 30441 raft_consensus.cc:493] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:05.345940 30441 raft_consensus.cc:3060] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:05.346843 30441 raft_consensus.cc:515] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 38671 } }
I20260812 06:18:05.347025 30441 leader_election.cc:304] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [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: fbdc67febde1435bbbaeb1cc8ec5f89f; no voters: 
I20260812 06:18:05.347296 30441 leader_election.cc:290] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:05.347532 30444 raft_consensus.cc:2804] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:05.347677 30441 ts_tablet_manager.cc:1434] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:18:05.347723 30427 heartbeater.cc:499] Master 127.29.84.190:45879 was elected leader, sending a full tablet report...
I20260812 06:18:05.347759 30444 raft_consensus.cc:697] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 1 LEADER]: Becoming Leader. State: Replica: fbdc67febde1435bbbaeb1cc8ec5f89f, State: Running, Role: LEADER
I20260812 06:18:05.347934 30444 consensus_queue.cc:237] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [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: "fbdc67febde1435bbbaeb1cc8ec5f89f" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 38671 } }
I20260812 06:18:05.349644 30279 catalog_manager.cc:5719] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f reported cstate change: term changed from 0 to 1, leader changed from <none> to fbdc67febde1435bbbaeb1cc8ec5f89f (127.29.84.129). New cstate: current_term: 1 leader_uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "fbdc67febde1435bbbaeb1cc8ec5f89f" member_type: VOTER last_known_addr { host: "127.29.84.129" port: 38671 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:05.416332 30034 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.014s	sys 0.012s
I20260812 06:18:05.554932 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushMRSOp(ef9fa577bff744d0aed49a154ae78820): perf score=15.086190
I20260812 06:18:05.757762 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushMRSOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.203s	user 0.157s	sys 0.035s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":923,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49331,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:18:05.758515 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling LogGCOp(ef9fa577bff744d0aed49a154ae78820): free 20743880 bytes of WAL
I20260812 06:18:05.758823 30352 log_reader.cc:385] T ef9fa577bff744d0aed49a154ae78820: removed 2 log segments from log reader
I20260812 06:18:05.758872 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000001 (ops 1-6)
I20260812 06:18:05.758903 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000002 (ops 7-11)
I20260812 06:18:05.763149 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: LogGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.004s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:18:05.763827 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:05.776103 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:05.776786 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820): 16411391 bytes on disk
I20260812 06:18:05.777729 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":116,"lbm_reads_lt_1ms":4}
I20260812 06:18:05.778352 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:05.931859 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.153s	user 0.114s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":764,"lbm_read_time_us":10702,"lbm_reads_lt_1ms":464,"lbm_write_time_us":26695,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":403,"threads_started":5,"update_count":2000}
I20260812 06:18:05.932571 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:05.981087 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.048s	user 0.029s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19676,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:05.981750 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:05.999346 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.017s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.000464 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:06.179490 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.179s	user 0.100s	sys 0.075s 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":940,"lbm_read_time_us":10137,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29006,"lbm_writes_lt_1ms":443,"mutex_wait_us":508,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":60672,"update_count":2000}
I20260812 06:18:06.180239 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=11.118625
I20260812 06:18:06.225651 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.045s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":19861,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:06.226737 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:06.244643 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:06.245508 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:06.386909 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.141s	user 0.117s	sys 0.024s 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":671,"lbm_read_time_us":7707,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28693,"lbm_writes_lt_1ms":443,"mutex_wait_us":113,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.387518 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:06.442305 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.055s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18776,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.442950 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:06.454556 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4495,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.455366 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:06.595279 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.140s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":9134,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2000}
I20260812 06:18:06.596118 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:06.655457 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.059s	user 0.028s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20632,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.656162 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:06.668367 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4687,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:06.669093 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:06.831382 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.162s	user 0.101s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":13398,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25905,"lbm_writes_lt_1ms":443,"mutex_wait_us":365,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:06.831990 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:06.870078 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.038s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:06.870605 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:06.992609 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.122s	user 0.094s	sys 0.027s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":389,"lbm_read_time_us":5849,"lbm_reads_lt_1ms":363,"lbm_write_time_us":24702,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":1500}
I20260812 06:18:06.993287 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:07.037415 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.044s	user 0.020s	sys 0.017s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.038226 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:07.050372 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4548,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.051273 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:07.186391 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.135s	user 0.126s	sys 0.008s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":625,"lbm_read_time_us":9622,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25377,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:18:07.187047 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:07.246248 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.059s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15872,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:07.246934 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:07.264775 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.018s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.265373 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushMRSOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:07.308471 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushMRSOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.043s	user 0.036s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":104,"dirs.run_cpu_time_us":302,"dirs.run_wall_time_us":1744,"drs_written":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2317,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:07.309198 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling LogGCOp(ef9fa577bff744d0aed49a154ae78820): free 124257242 bytes of WAL
I20260812 06:18:07.309445 30352 log_reader.cc:385] T ef9fa577bff744d0aed49a154ae78820: removed 12 log segments from log reader
I20260812 06:18:07.309489 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000003 (ops 12-16)
I20260812 06:18:07.309520 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000004 (ops 17-21)
I20260812 06:18:07.309595 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000005 (ops 22-26)
I20260812 06:18:07.309672 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000006 (ops 27-31)
I20260812 06:18:07.309720 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000007 (ops 32-36)
I20260812 06:18:07.309791 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000008 (ops 37-41)
I20260812 06:18:07.309837 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000009 (ops 42-46)
I20260812 06:18:07.309885 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000010 (ops 47-51)
I20260812 06:18:07.309921 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000011 (ops 52-56)
I20260812 06:18:07.309968 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000012 (ops 57-61)
I20260812 06:18:07.310011 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000013 (ops 62-66)
I20260812 06:18:07.310053 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000014 (ops 67-70)
I20260812 06:18:07.339426 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: LogGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.030s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:18:07.340505 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=3.181125
I20260812 06:18:07.362540 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.022s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":5727,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:07.363337 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820): 483 bytes on disk
I20260812 06:18:07.363889 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:18:07.364562 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:07.379415 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":5725,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:18:07.379947 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:07.604861 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.224s	user 0.157s	sys 0.066s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":871,"lbm_read_time_us":13988,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35406,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":20352,"thread_start_us":100,"threads_started":1,"update_count":3000}
I20260812 06:18:07.605655 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:07.674292 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.068s	user 0.032s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26553,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.674993 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:07.690891 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.016s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5034,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.691409 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:07.875540 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.184s	user 0.131s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":13349,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30221,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:18:07.876076 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:07.946328 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.070s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:07.946928 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:07.958063 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4301,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:07.958743 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:08.150389 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.191s	user 0.141s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":533,"lbm_read_time_us":13188,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31590,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":2500}
I20260812 06:18:08.151566 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=12.110812
I20260812 06:18:08.191377 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.040s	user 0.024s	sys 0.015s Metrics: {"bytes_written":13702316,"delete_count":0,"lbm_write_time_us":17396,"lbm_writes_lt_1ms":337,"reinsert_count":0,"update_count":1670}
I20260812 06:18:08.192072 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.196750
I20260812 06:18:08.204177 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.004s	sys 0.004s Metrics: {"bytes_written":2707805,"delete_count":0,"lbm_write_time_us":3518,"lbm_writes_lt_1ms":69,"reinsert_count":0,"update_count":330}
I20260812 06:18:08.204862 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:08.377429 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.172s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672249,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1135,"lbm_read_time_us":10142,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24812,"lbm_writes_lt_1ms":443,"mutex_wait_us":389,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16512,"update_count":2000}
I20260812 06:18:08.378042 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:08.439481 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.061s	user 0.039s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24576,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.440135 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:08.454860 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.014s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4537,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.455580 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:08.626884 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.171s	user 0.143s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":621,"lbm_read_time_us":11938,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30805,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33024,"update_count":2500}
I20260812 06:18:08.627606 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:08.689877 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.062s	user 0.041s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26790,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:08.690483 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:08.703253 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4101,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:08.703992 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:08.864558 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.160s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":525,"lbm_read_time_us":11621,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32534,"lbm_writes_lt_1ms":543,"mutex_wait_us":1275,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":66560,"update_count":2500}
I20260812 06:18:08.867650 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=11.118625
I20260812 06:18:08.908620 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.041s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12471587,"delete_count":0,"lbm_write_time_us":18272,"lbm_writes_lt_1ms":307,"reinsert_count":0,"update_count":1520}
I20260812 06:18:08.909235 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:08.920056 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:18:08.920553 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushMRSOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:08.955847 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushMRSOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.035s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":166,"dirs.run_cpu_time_us":273,"dirs.run_wall_time_us":1678,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2051,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:08.956784 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling LogGCOp(ef9fa577bff744d0aed49a154ae78820): free 124710321 bytes of WAL
I20260812 06:18:08.957051 30352 log_reader.cc:385] T ef9fa577bff744d0aed49a154ae78820: removed 12 log segments from log reader
I20260812 06:18:08.957099 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000015 (ops 71-75)
I20260812 06:18:08.957134 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000016 (ops 76-80)
I20260812 06:18:08.957208 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000017 (ops 81-85)
I20260812 06:18:08.957278 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000018 (ops 86-90)
I20260812 06:18:08.957326 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000019 (ops 91-95)
I20260812 06:18:08.957401 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000020 (ops 96-100)
I20260812 06:18:08.957459 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000021 (ops 101-105)
I20260812 06:18:08.957500 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000022 (ops 106-110)
I20260812 06:18:08.957551 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000023 (ops 111-115)
I20260812 06:18:08.957599 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000024 (ops 116-120)
I20260812 06:18:08.957643 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000025 (ops 121-125)
I20260812 06:18:08.957685 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000026 (ops 126-130)
I20260812 06:18:08.986642 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: LogGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.030s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:08.987208 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=3.181125
I20260812 06:18:09.001971 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5742,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:09.002804 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:09.015023 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.003s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4174,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:09.015799 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820): 472 bytes on disk
I20260812 06:18:09.016456 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:18:09.017221 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:09.207993 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.191s	user 0.139s	sys 0.052s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":689,"lbm_read_time_us":12365,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41349,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28288,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:09.208847 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:09.269418 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.060s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25375,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.270097 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:09.282543 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.283164 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:09.450198 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.167s	user 0.114s	sys 0.048s 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":369,"lbm_read_time_us":12505,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30804,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:18:09.451397 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=12.110812
I20260812 06:18:09.501806 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.050s	user 0.035s	sys 0.012s Metrics: {"bytes_written":13825384,"delete_count":0,"lbm_write_time_us":22339,"lbm_writes_lt_1ms":340,"reinsert_count":0,"update_count":1685}
I20260812 06:18:09.502629 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.196750
I20260812 06:18:09.514351 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":3309,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:18:09.514961 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:09.703724 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.189s	user 0.132s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672241,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":10437,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31125,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2000}
I20260812 06:18:09.704420 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:09.768642 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.064s	user 0.034s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25516,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:09.769243 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:09.789738 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.020s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:09.790644 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:10.000880 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.210s	user 0.116s	sys 0.081s 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":318,"lbm_read_time_us":13687,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35489,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:18:10.001997 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:10.062117 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.060s	user 0.032s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22836,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:10.062826 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:10.079859 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.017s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:10.080500 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:10.254673 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.174s	user 0.130s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":881,"lbm_read_time_us":11700,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31909,"lbm_writes_lt_1ms":543,"mutex_wait_us":370,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:18:10.255635 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=10.126437
I20260812 06:18:10.291205 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.035s	user 0.028s	sys 0.007s Metrics: {"bytes_written":12348516,"delete_count":0,"lbm_write_time_us":15042,"lbm_writes_lt_1ms":304,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1505}
I20260812 06:18:10.291880 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:10.313102 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:18:10.313968 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:10.454759 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.141s	user 0.104s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1108,"lbm_read_time_us":9719,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27815,"lbm_writes_lt_1ms":443,"mutex_wait_us":402,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":75520,"update_count":2000}
I20260812 06:18:10.455744 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=11.118625
I20260812 06:18:10.489267 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.033s	user 0.018s	sys 0.013s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14930,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:10.489851 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:10.503896 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.014s	user 0.001s	sys 0.012s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5559,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:10.504369 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushMRSOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:10.535140 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushMRSOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.031s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":263,"dirs.run_wall_time_us":2030,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1604,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:10.535844 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling LogGCOp(ef9fa577bff744d0aed49a154ae78820): free 121006659 bytes of WAL
I20260812 06:18:10.536087 30352 log_reader.cc:385] T ef9fa577bff744d0aed49a154ae78820: removed 12 log segments from log reader
I20260812 06:18:10.536132 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000027 (ops 131-135)
I20260812 06:18:10.536162 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000028 (ops 136-140)
I20260812 06:18:10.536204 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000029 (ops 141-145)
I20260812 06:18:10.536253 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000030 (ops 146-150)
I20260812 06:18:10.536283 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000031 (ops 151-155)
I20260812 06:18:10.536332 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000032 (ops 156-160)
I20260812 06:18:10.536375 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000033 (ops 161-165)
I20260812 06:18:10.536417 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000034 (ops 166-170)
I20260812 06:18:10.536458 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000035 (ops 171-175)
I20260812 06:18:10.536499 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000036 (ops 176-180)
I20260812 06:18:10.536540 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000037 (ops 181-184)
I20260812 06:18:10.536580 30352 log.cc:1079] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: Deleting log segment in path: /tmp/dist-test-taskBKcHv5/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515479343060-30034-0/minicluster-data/ts-0-root/wals/ef9fa577bff744d0aed49a154ae78820/wal-000000038 (ops 185-189)
I20260812 06:18:10.563549 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: LogGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.028s	user 0.004s	sys 0.023s Metrics: {}
I20260812 06:18:10.564092 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=3.181125
I20260812 06:18:10.576680 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4800077,"delete_count":0,"lbm_write_time_us":4822,"lbm_writes_lt_1ms":120,"reinsert_count":0,"update_count":585}
I20260812 06:18:10.577157 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=2.188937
I20260812 06:18:10.586627 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3405230,"delete_count":0,"lbm_write_time_us":3532,"lbm_writes_lt_1ms":86,"reinsert_count":0,"update_count":415}
I20260812 06:18:10.587206 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820): 463 bytes on disk
I20260812 06:18:10.587693 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: UndoDeltaBlockGCOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:18:10.588323 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820): perf score=1.000000
I20260812 06:18:10.788692 30034 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.372s	user 2.026s	sys 0.172s
I20260812 06:18:10.791706 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: MajorDeltaCompactionOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.203s	user 0.127s	sys 0.069s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877321,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1079,"lbm_read_time_us":13525,"lbm_reads_lt_1ms":674,"lbm_write_time_us":41413,"lbm_writes_lt_1ms":643,"mutex_wait_us":365,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12672,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:10.792317 30428 maintenance_manager.cc:419] P fbdc67febde1435bbbaeb1cc8ec5f89f: Scheduling FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820): perf score=14.095187
I20260812 06:18:10.821738 30034 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.001s	sys 0.000s
I20260812 06:18:10.822352 30034 tablet_server.cc:179] TabletServer@127.29.84.129:0 shutting down...
I20260812 06:18:10.848714 30352 maintenance_manager.cc:643] P fbdc67febde1435bbbaeb1cc8ec5f89f: FlushDeltaMemStoresOp(ef9fa577bff744d0aed49a154ae78820) complete. Timing: real 0.056s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25259,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:10.849392 30034 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:10.849728 30034 tablet_replica.cc:333] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f: stopping tablet replica
I20260812 06:18:10.849879 30034 raft_consensus.cc:2243] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.850116 30034 raft_consensus.cc:2272] T ef9fa577bff744d0aed49a154ae78820 P fbdc67febde1435bbbaeb1cc8ec5f89f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.853690 30034 tablet_server.cc:196] TabletServer@127.29.84.129:0 shutdown complete.
I20260812 06:18:10.856630 30034 master.cc:562] Master@127.29.84.190:45879 shutting down...
I20260812 06:18:10.860868 30034 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:10.861071 30034 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:10.861146 30034 tablet_replica.cc:333] T 00000000000000000000000000000000 P e2c1b368f5824b54a4be2a534ff096d9: stopping tablet replica
I20260812 06:18:10.875370 30034 master.cc:584] Master@127.29.84.190:45879 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5776 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11614 ms total)

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