[==========] 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:28.617394 12082 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.204.190:36791
I20260812 06:17:28.618333 12082 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:28.618892 12082 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.625079 12094 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:28.625123 12090 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:28.625370 12091 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:28.625384 12082 server_base.cc:1061] running on GCE node
I20260812 06:17:28.625826 12082 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.625933 12082 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:28.625982 12082 hybrid_clock.cc:648] HybridClock initialized: now 1786515448625979 us; error 0 us; skew 500 ppm
I20260812 06:17:28.627591 12082 webserver.cc:533] Webserver started at http://127.11.204.190:38019/ using document root <none> and password file <none>
I20260812 06:17:28.628101 12082 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.628161 12082 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.628437 12082 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.629967 12082 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/master-0-root/instance:
uuid: "27861ee2411d497baf5650e965a4009c"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-04bb"
I20260812 06:17:28.633186 12082 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:17:28.635049 12103 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:28.635991 12082 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:28.636121 12082 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/master-0-root
uuid: "27861ee2411d497baf5650e965a4009c"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-04bb"
I20260812 06:17:28.636219 12082 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-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:28.673107 12082 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.673728 12082 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:28.673915 12082 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.681185 12082 rpc_server.cc:307] RPC server started. Bound to: 127.11.204.190:36791
I20260812 06:17:28.681205 12186 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.204.190:36791 every 8 connection(s)
I20260812 06:17:28.683351 12187 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:28.688377 12187 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: Bootstrap starting.
I20260812 06:17:28.690702 12187 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.691876 12187 log.cc:826] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:28.693524 12187 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: No bootstrap required, opened a new log
I20260812 06:17:28.696108 12187 raft_consensus.cc:359] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27861ee2411d497baf5650e965a4009c" member_type: VOTER }
I20260812 06:17:28.696266 12187 raft_consensus.cc:385] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.696394 12187 raft_consensus.cc:740] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 27861ee2411d497baf5650e965a4009c, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.696970 12187 consensus_queue.cc:260] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [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: "27861ee2411d497baf5650e965a4009c" member_type: VOTER }
I20260812 06:17:28.697131 12187 raft_consensus.cc:399] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.697228 12187 raft_consensus.cc:493] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.697377 12187 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.698100 12187 raft_consensus.cc:515] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27861ee2411d497baf5650e965a4009c" member_type: VOTER }
I20260812 06:17:28.698524 12187 leader_election.cc:304] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [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: 27861ee2411d497baf5650e965a4009c; no voters: 
I20260812 06:17:28.698837 12187 leader_election.cc:290] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.698988 12194 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.699257 12194 raft_consensus.cc:697] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 1 LEADER]: Becoming Leader. State: Replica: 27861ee2411d497baf5650e965a4009c, State: Running, Role: LEADER
I20260812 06:17:28.699630 12194 consensus_queue.cc:237] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [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: "27861ee2411d497baf5650e965a4009c" member_type: VOTER }
I20260812 06:17:28.699803 12187 sys_catalog.cc:565] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:28.701460 12196 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [sys.catalog]: SysCatalogTable state changed. Reason: New leader 27861ee2411d497baf5650e965a4009c. Latest consensus state: current_term: 1 leader_uuid: "27861ee2411d497baf5650e965a4009c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27861ee2411d497baf5650e965a4009c" member_type: VOTER } }
I20260812 06:17:28.701502 12195 sys_catalog.cc:455] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "27861ee2411d497baf5650e965a4009c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "27861ee2411d497baf5650e965a4009c" member_type: VOTER } }
I20260812 06:17:28.701575 12196 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.701609 12195 sys_catalog.cc:458] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:28.702186 12082 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:17:28.704280 12220 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:17:28.704368 12220 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:17:28.704480 12209 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:28.705212 12209 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:28.709293 12209 catalog_manager.cc:1383] Generated new cluster ID: 81c2f261946b45ecacb14d69d76cd4a7
I20260812 06:17:28.709357 12209 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:28.718300 12209 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:28.719050 12209 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:28.723294 12209 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: Generated new TSK 0
I20260812 06:17:28.723821 12209 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:28.734601 12082 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:28.737160 12226 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:28.737166 12225 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:17:28.737310 12082 server_base.cc:1061] running on GCE node
W20260812 06:17:28.737203 12229 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:28.737610 12082 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:28.737679 12082 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:28.737725 12082 hybrid_clock.cc:648] HybridClock initialized: now 1786515448737723 us; error 0 us; skew 500 ppm
I20260812 06:17:28.738680 12082 webserver.cc:533] Webserver started at http://127.11.204.129:43095/ using document root <none> and password file <none>
I20260812 06:17:28.738873 12082 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:28.738943 12082 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:28.739020 12082 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:28.739388 12082 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/instance:
uuid: "0a89217da1fa4b57b59e702dfd83df21"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-04bb"
I20260812 06:17:28.741076 12082 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:28.742110 12239 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:28.742359 12082 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:28.742429 12082 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root
uuid: "0a89217da1fa4b57b59e702dfd83df21"
format_stamp: "Formatted at 2026-08-12 06:17:28 on dist-test-slave-04bb"
I20260812 06:17:28.742509 12082 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-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:28.762400 12082 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:28.762825 12082 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:28.763309 12082 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:28.764096 12082 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:28.764144 12082 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.764228 12082 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:28.764271 12082 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:28.771263 12082 rpc_server.cc:307] RPC server started. Bound to: 127.11.204.129:44675
I20260812 06:17:28.771323 12347 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.204.129:44675 every 8 connection(s)
I20260812 06:17:28.781306 12350 heartbeater.cc:344] Connected to a master server at 127.11.204.190:36791
I20260812 06:17:28.781540 12350 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:28.781970 12350 heartbeater.cc:507] Master 127.11.204.190:36791 requested a full tablet report, sending...
I20260812 06:17:28.783458 12129 ts_manager.cc:194] Registered new tserver with Master: 0a89217da1fa4b57b59e702dfd83df21 (127.11.204.129:44675)
I20260812 06:17:28.784195 12082 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012294993s
I20260812 06:17:28.785014 12129 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38550
I20260812 06:17:28.793499 12129 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38560:
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:28.807827 12280 tablet_service.cc:1511] Processing CreateTablet for tablet 8d73923954044ed78f946f47e65c4b86 (DEFAULT_TABLE table=heavy-update-compaction-test [id=550da9e2f39b4a92b604361c60cee0fd]), partition=
I20260812 06:17:28.808255 12280 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 8d73923954044ed78f946f47e65c4b86. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:28.810415 12374 tablet_bootstrap.cc:492] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Bootstrap starting.
I20260812 06:17:28.811617 12374 tablet_bootstrap.cc:654] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:28.812732 12374 tablet_bootstrap.cc:492] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: No bootstrap required, opened a new log
I20260812 06:17:28.812837 12374 ts_tablet_manager.cc:1403] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:28.813248 12374 raft_consensus.cc:359] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a89217da1fa4b57b59e702dfd83df21" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 44675 } }
I20260812 06:17:28.813341 12374 raft_consensus.cc:385] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:28.813387 12374 raft_consensus.cc:740] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0a89217da1fa4b57b59e702dfd83df21, State: Initialized, Role: FOLLOWER
I20260812 06:17:28.813547 12374 consensus_queue.cc:260] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [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: "0a89217da1fa4b57b59e702dfd83df21" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 44675 } }
I20260812 06:17:28.813637 12374 raft_consensus.cc:399] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:28.813692 12374 raft_consensus.cc:493] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:28.813751 12374 raft_consensus.cc:3060] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:28.814507 12374 raft_consensus.cc:515] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a89217da1fa4b57b59e702dfd83df21" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 44675 } }
I20260812 06:17:28.814651 12374 leader_election.cc:304] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [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: 0a89217da1fa4b57b59e702dfd83df21; no voters: 
I20260812 06:17:28.814857 12374 leader_election.cc:290] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:28.814983 12377 raft_consensus.cc:2804] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:28.815275 12377 raft_consensus.cc:697] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 1 LEADER]: Becoming Leader. State: Replica: 0a89217da1fa4b57b59e702dfd83df21, State: Running, Role: LEADER
I20260812 06:17:28.815316 12374 ts_tablet_manager.cc:1434] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:28.815703 12350 heartbeater.cc:499] Master 127.11.204.190:36791 was elected leader, sending a full tablet report...
I20260812 06:17:28.815722 12377 consensus_queue.cc:237] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [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: "0a89217da1fa4b57b59e702dfd83df21" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 44675 } }
I20260812 06:17:28.818220 12129 catalog_manager.cc:5719] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0a89217da1fa4b57b59e702dfd83df21 (127.11.204.129). New cstate: current_term: 1 leader_uuid: "0a89217da1fa4b57b59e702dfd83df21" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0a89217da1fa4b57b59e702dfd83df21" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 44675 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:28.889567 12082 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.028s	sys 0.003s
I20260812 06:17:29.022310 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushMRSOp(8d73923954044ed78f946f47e65c4b86): perf score=19.054940
I20260812 06:17:29.228044 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushMRSOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.205s	user 0.148s	sys 0.051s Metrics: {"bytes_written":13127976,"cfile_init":1,"compiler_manager_pool.queue_time_us":237,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":309,"dirs.run_wall_time_us":1095,"drs_written":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4,"lbm_write_time_us":52542,"lbm_writes_lt_1ms":777,"mutex_wait_us":202,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":185600,"thread_start_us":159,"threads_started":1,"update_count":1600}
I20260812 06:17:29.229302 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling LogGCOp(8d73923954044ed78f946f47e65c4b86): free 20743880 bytes of WAL
I20260812 06:17:29.229616 12248 log_reader.cc:385] T 8d73923954044ed78f946f47e65c4b86: removed 2 log segments from log reader
I20260812 06:17:29.229684 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000001 (ops 1-6)
I20260812 06:17:29.229735 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000002 (ops 7-11)
I20260812 06:17:29.236106 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: LogGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:29.236433 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:29.262089 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.025s	user 0.010s	sys 0.010s Metrics: {"bytes_written":3692409,"delete_count":0,"lbm_write_time_us":5298,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.262584 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:29.272259 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3907,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:29.272699 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86): 16411395 bytes on disk
I20260812 06:17:29.273226 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:29.273595 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:29.460767 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.187s	user 0.122s	sys 0.065s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774790,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1011,"lbm_read_time_us":14526,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31642,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":363,"threads_started":5,"update_count":2500}
I20260812 06:17:29.461277 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:29.507834 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.046s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19289,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.508301 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:29.518568 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.519066 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:29.648952 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.130s	user 0.082s	sys 0.047s 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":201,"lbm_read_time_us":10149,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26028,"lbm_writes_lt_1ms":443,"mutex_wait_us":39,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:29.649470 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:29.694350 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.045s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17715,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.694761 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:29.705847 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4434,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.706363 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:29.837101 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.131s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":155,"lbm_read_time_us":10654,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26133,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:29.837735 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:29.880119 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.042s	user 0.017s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17336,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:29.880650 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:29.893925 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:29.894498 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.032514 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.138s	user 0.113s	sys 0.025s 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":165,"lbm_read_time_us":9609,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27509,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2000}
I20260812 06:17:30.033118 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:30.085500 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.052s	user 0.032s	sys 0.019s Metrics: {"bytes_written":12389540,"delete_count":0,"lbm_write_time_us":18510,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1510}
I20260812 06:17:30.086097 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:30.102488 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":6195,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:30.103091 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.256963 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.154s	user 0.114s	sys 0.039s 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":218,"lbm_read_time_us":12667,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25205,"lbm_writes_lt_1ms":443,"mutex_wait_us":60,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:30.257591 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:30.303227 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.045s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.303711 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:30.314543 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.315116 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.430008 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.115s	user 0.074s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":123,"lbm_read_time_us":7782,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22582,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:30.430598 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:30.473354 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.043s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17348,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.473871 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:30.488188 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.488719 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushMRSOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.517185 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushMRSOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.028s	user 0.027s	sys 0.001s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":80,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1350,"drs_written":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1542,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:30.517966 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling LogGCOp(8d73923954044ed78f946f47e65c4b86): free 120100342 bytes of WAL
I20260812 06:17:30.518198 12248 log_reader.cc:385] T 8d73923954044ed78f946f47e65c4b86: removed 12 log segments from log reader
I20260812 06:17:30.518242 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000003 (ops 12-16)
I20260812 06:17:30.518273 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000004 (ops 17-21)
I20260812 06:17:30.518342 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000005 (ops 22-26)
I20260812 06:17:30.518384 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000006 (ops 27-30)
I20260812 06:17:30.518426 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000007 (ops 31-35)
I20260812 06:17:30.518464 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000008 (ops 36-40)
I20260812 06:17:30.518505 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000009 (ops 41-44)
I20260812 06:17:30.518544 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000010 (ops 45-49)
I20260812 06:17:30.518581 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000011 (ops 50-54)
I20260812 06:17:30.518620 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000012 (ops 55-58)
I20260812 06:17:30.518659 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000013 (ops 59-63)
I20260812 06:17:30.518698 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000014 (ops 64-68)
I20260812 06:17:30.547354 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: LogGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:30.547775 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86): 462 bytes on disk
I20260812 06:17:30.548449 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:30.548972 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=3.181125
I20260812 06:17:30.561111 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.012s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4710,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:30.561542 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:30.571146 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3566,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:30.571714 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.741233 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.169s	user 0.123s	sys 0.046s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":546,"lbm_read_time_us":12076,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35189,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28544,"thread_start_us":76,"threads_started":1,"update_count":3000}
I20260812 06:17:30.741889 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:30.788674 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.046s	user 0.026s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18360,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:30.789286 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:30.799496 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:30.800040 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:30.947003 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.147s	user 0.098s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":569,"lbm_read_time_us":10180,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30380,"lbm_writes_lt_1ms":543,"mutex_wait_us":332,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:30.947813 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:30.994786 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.047s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21397,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:30.995224 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.005882 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.006567 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:31.134794 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.128s	user 0.097s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":106,"lbm_read_time_us":9966,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23088,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:31.135489 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:31.179766 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.044s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14191,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.180354 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.197386 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6386,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.197944 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:31.347609 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.149s	user 0.097s	sys 0.052s 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":1113,"lbm_read_time_us":11940,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25070,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:31.348330 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:31.385566 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.037s	user 0.012s	sys 0.024s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16225,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.386202 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.403713 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.017s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.404266 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:31.539037 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.135s	user 0.094s	sys 0.040s 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":1005,"lbm_read_time_us":8593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28855,"lbm_writes_lt_1ms":443,"mutex_wait_us":323,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:17:31.539742 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=10.126437
I20260812 06:17:31.574292 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.034s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14673,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:31.575093 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.602670 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.027s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6528,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.603142 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.617527 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.618023 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:31.765483 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.147s	user 0.121s	sys 0.025s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774807,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":853,"lbm_read_time_us":12390,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29530,"lbm_writes_lt_1ms":543,"mutex_wait_us":91,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:17:31.766183 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=11.118625
I20260812 06:17:31.806070 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.040s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15832,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:31.806872 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.826673 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.018s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4418,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:31.827200 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.840668 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5156,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.841152 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushMRSOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:31.873458 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushMRSOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1371,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1627,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:31.874349 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling LogGCOp(8d73923954044ed78f946f47e65c4b86): free 121006432 bytes of WAL
I20260812 06:17:31.874603 12248 log_reader.cc:385] T 8d73923954044ed78f946f47e65c4b86: removed 12 log segments from log reader
I20260812 06:17:31.874668 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000015 (ops 69-73)
I20260812 06:17:31.874758 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000016 (ops 74-78)
I20260812 06:17:31.874811 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000017 (ops 79-83)
I20260812 06:17:31.874850 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000018 (ops 84-88)
I20260812 06:17:31.874886 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000019 (ops 89-93)
I20260812 06:17:31.874917 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000020 (ops 94-98)
I20260812 06:17:31.874943 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000021 (ops 99-102)
I20260812 06:17:31.874970 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000022 (ops 103-107)
I20260812 06:17:31.875003 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000023 (ops 108-112)
I20260812 06:17:31.875041 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000024 (ops 113-117)
I20260812 06:17:31.875078 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000025 (ops 118-122)
I20260812 06:17:31.875115 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000026 (ops 123-127)
I20260812 06:17:31.902899 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: LogGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.028s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:17:31.903335 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=3.181125
I20260812 06:17:31.921208 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6789,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:31.921630 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:31.930923 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3729,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:31.931332 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:32.133150 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.202s	user 0.121s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1160,"lbm_read_time_us":14574,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41920,"lbm_writes_lt_1ms":743,"mutex_wait_us":360,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":27008,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:17:32.133719 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86): 463 bytes on disk
I20260812 06:17:32.134248 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:17:32.134887 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:32.186682 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.052s	user 0.042s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.187245 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:32.208765 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.021s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.209214 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:32.360306 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.151s	user 0.110s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":511,"lbm_read_time_us":9342,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30090,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1922048,"update_count":2500}
I20260812 06:17:32.361054 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:32.419956 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24045,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.420481 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:32.432001 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4379,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.432653 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:32.621688 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.188s	user 0.122s	sys 0.063s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":850,"lbm_read_time_us":12498,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32600,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":349,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:17:32.622329 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:32.681084 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.059s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.681535 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:32.692061 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.693579 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:32.876591 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.183s	user 0.108s	sys 0.072s 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":1042,"lbm_read_time_us":13066,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32844,"lbm_writes_lt_1ms":543,"mutex_wait_us":302,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:17:32.877377 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:32.951746 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.074s	user 0.036s	sys 0.034s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":28370,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:32.952594 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:32.969687 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6486,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:32.970366 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:33.147428 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.177s	user 0.125s	sys 0.045s 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":594,"lbm_read_time_us":13094,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30256,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16896,"update_count":2500}
I20260812 06:17:33.148072 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:33.213634 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.065s	user 0.037s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21666,"lbm_writes_lt_1ms":403,"mutex_wait_us":2,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.214238 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:33.230845 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6282,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.231457 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:33.430279 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.199s	user 0.114s	sys 0.073s 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":1046,"lbm_read_time_us":14280,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30421,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:33.431051 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:33.497633 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.066s	user 0.033s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25262,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:33.498255 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:33.511013 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5044,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:33.511606 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushMRSOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:33.546612 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushMRSOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.035s	user 0.025s	sys 0.003s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1345,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1719,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:33.547369 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling LogGCOp(8d73923954044ed78f946f47e65c4b86): free 133024589 bytes of WAL
I20260812 06:17:33.547595 12248 log_reader.cc:385] T 8d73923954044ed78f946f47e65c4b86: removed 13 log segments from log reader
I20260812 06:17:33.547639 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000027 (ops 128-132)
I20260812 06:17:33.547669 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000028 (ops 133-137)
I20260812 06:17:33.547734 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000029 (ops 138-142)
I20260812 06:17:33.547775 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000030 (ops 143-147)
I20260812 06:17:33.547828 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000031 (ops 148-152)
I20260812 06:17:33.547889 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000032 (ops 153-157)
I20260812 06:17:33.547930 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000033 (ops 158-162)
I20260812 06:17:33.547971 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000034 (ops 163-166)
I20260812 06:17:33.548012 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000035 (ops 167-171)
I20260812 06:17:33.548051 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000036 (ops 172-176)
I20260812 06:17:33.548089 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000037 (ops 177-181)
I20260812 06:17:33.548130 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000038 (ops 182-186)
I20260812 06:17:33.548168 12248 log.cc:1079] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/8d73923954044ed78f946f47e65c4b86/wal-000000039 (ops 187-191)
I20260812 06:17:33.578732 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: LogGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:17:33.579212 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=3.181125
I20260812 06:17:33.591933 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:33.592334 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86): 492 bytes on disk
I20260812 06:17:33.592752 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: UndoDeltaBlockGCOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:17:33.593237 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=2.188937
I20260812 06:17:33.602880 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3833,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:33.603232 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:33.794518 12082 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.905s	user 1.810s	sys 0.162s
I20260812 06:17:33.840135 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.237s	user 0.156s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":16129,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38004,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":3500}
I20260812 06:17:33.840768 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86): perf score=14.095187
I20260812 06:17:33.875947 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: FlushDeltaMemStoresOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.035s	user 0.013s	sys 0.021s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17253,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:33.876657 12351 maintenance_manager.cc:419] P 0a89217da1fa4b57b59e702dfd83df21: Scheduling MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86): perf score=1.000000
I20260812 06:17:33.917202 12082 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.122s	user 0.004s	sys 0.000s
I20260812 06:17:33.918046 12082 tablet_server.cc:179] TabletServer@127.11.204.129:0 shutting down...
I20260812 06:17:34.001235 12248 maintenance_manager.cc:643] P 0a89217da1fa4b57b59e702dfd83df21: MajorDeltaCompactionOp(8d73923954044ed78f946f47e65c4b86) complete. Timing: real 0.124s	user 0.098s	sys 0.025s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672156,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1171,"lbm_read_time_us":9846,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25854,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":670,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:17:34.002013 12082 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:34.002444 12082 tablet_replica.cc:333] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21: stopping tablet replica
I20260812 06:17:34.002705 12082 raft_consensus.cc:2243] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.002947 12082 raft_consensus.cc:2272] T 8d73923954044ed78f946f47e65c4b86 P 0a89217da1fa4b57b59e702dfd83df21 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.019050 12082 tablet_server.cc:196] TabletServer@127.11.204.129:0 shutdown complete.
I20260812 06:17:34.039943 12082 master.cc:562] Master@127.11.204.190:36791 shutting down...
I20260812 06:17:34.043502 12082 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:34.043648 12082 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:34.043706 12082 tablet_replica.cc:333] T 00000000000000000000000000000000 P 27861ee2411d497baf5650e965a4009c: stopping tablet replica
I20260812 06:17:34.055881 12082 master.cc:584] Master@127.11.204.190:36791 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5531 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:34.148429 12082 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.11.204.190:44501
I20260812 06:17:34.148859 12082 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:34.150931 12413 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:34.150945 12082 server_base.cc:1061] running on GCE node
W20260812 06:17:34.150940 12409 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:34.150949 12411 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:34.151450 12082 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:34.151517 12082 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:34.151543 12082 hybrid_clock.cc:648] HybridClock initialized: now 1786515454151542 us; error 0 us; skew 500 ppm
I20260812 06:17:34.152380 12082 webserver.cc:533] Webserver started at http://127.11.204.190:41891/ using document root <none> and password file <none>
I20260812 06:17:34.152639 12082 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:34.152709 12082 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:34.152794 12082 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:34.153175 12082 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/master-0-root/instance:
uuid: "c3bd4613156e4b189732760215c86879"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-04bb"
I20260812 06:17:34.154639 12082 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:34.155493 12422 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:34.155723 12082 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.155814 12082 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/master-0-root
uuid: "c3bd4613156e4b189732760215c86879"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-04bb"
I20260812 06:17:34.155897 12082 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-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:34.170471 12082 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:34.170830 12082 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:34.174942 12082 rpc_server.cc:307] RPC server started. Bound to: 127.11.204.190:44501
I20260812 06:17:34.182323 12501 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.204.190:44501 every 8 connection(s)
I20260812 06:17:34.191970 12504 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:34.193825 12504 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879: Bootstrap starting.
I20260812 06:17:34.194607 12504 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:34.195663 12504 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879: No bootstrap required, opened a new log
I20260812 06:17:34.196082 12504 raft_consensus.cc:359] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3bd4613156e4b189732760215c86879" member_type: VOTER }
I20260812 06:17:34.196165 12504 raft_consensus.cc:385] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:34.196188 12504 raft_consensus.cc:740] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c3bd4613156e4b189732760215c86879, State: Initialized, Role: FOLLOWER
I20260812 06:17:34.196388 12504 consensus_queue.cc:260] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [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: "c3bd4613156e4b189732760215c86879" member_type: VOTER }
I20260812 06:17:34.196463 12504 raft_consensus.cc:399] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:34.196537 12504 raft_consensus.cc:493] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:34.196615 12504 raft_consensus.cc:3060] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:34.197304 12504 raft_consensus.cc:515] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3bd4613156e4b189732760215c86879" member_type: VOTER }
I20260812 06:17:34.197443 12504 leader_election.cc:304] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [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: c3bd4613156e4b189732760215c86879; no voters: 
I20260812 06:17:34.197657 12504 leader_election.cc:290] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:34.197784 12510 raft_consensus.cc:2804] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:34.198024 12510 raft_consensus.cc:697] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 1 LEADER]: Becoming Leader. State: Replica: c3bd4613156e4b189732760215c86879, State: Running, Role: LEADER
I20260812 06:17:34.198182 12504 sys_catalog.cc:565] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:34.198199 12510 consensus_queue.cc:237] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [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: "c3bd4613156e4b189732760215c86879" member_type: VOTER }
I20260812 06:17:34.198693 12513 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [sys.catalog]: SysCatalogTable state changed. Reason: New leader c3bd4613156e4b189732760215c86879. Latest consensus state: current_term: 1 leader_uuid: "c3bd4613156e4b189732760215c86879" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3bd4613156e4b189732760215c86879" member_type: VOTER } }
I20260812 06:17:34.198788 12513 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:34.198678 12512 sys_catalog.cc:455] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "c3bd4613156e4b189732760215c86879" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c3bd4613156e4b189732760215c86879" member_type: VOTER } }
I20260812 06:17:34.198917 12512 sys_catalog.cc:458] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:34.199324 12519 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:34.199954 12519 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:34.200170 12082 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:34.202550 12519 catalog_manager.cc:1383] Generated new cluster ID: 95022f86f9284ef895d03e8deefd3a10
I20260812 06:17:34.202607 12519 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:34.213750 12519 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:34.214226 12519 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:34.219431 12519 catalog_manager.cc:6092] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879: Generated new TSK 0
I20260812 06:17:34.219599 12519 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:34.232311 12082 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:34.234357 12546 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:34.234354 12542 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:34.234411 12543 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:34.234543 12082 server_base.cc:1061] running on GCE node
I20260812 06:17:34.234746 12082 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:34.234807 12082 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:34.234835 12082 hybrid_clock.cc:648] HybridClock initialized: now 1786515454234835 us; error 0 us; skew 500 ppm
I20260812 06:17:34.235663 12082 webserver.cc:533] Webserver started at http://127.11.204.129:38461/ using document root <none> and password file <none>
I20260812 06:17:34.235852 12082 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:34.235921 12082 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:34.235999 12082 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:34.236377 12082 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/instance:
uuid: "c57d536a0d704683a54989490ad60d0c"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-04bb"
I20260812 06:17:34.237882 12082 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.238847 12554 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:34.239199 12082 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:34.239291 12082 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root
uuid: "c57d536a0d704683a54989490ad60d0c"
format_stamp: "Formatted at 2026-08-12 06:17:34 on dist-test-slave-04bb"
I20260812 06:17:34.239374 12082 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-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:34.246568 12082 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:34.246893 12082 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:34.247166 12082 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:34.247598 12082 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:34.247658 12082 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:34.247751 12082 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:34.247793 12082 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:34.252220 12082 rpc_server.cc:307] RPC server started. Bound to: 127.11.204.129:38495
I20260812 06:17:34.253119 12648 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.11.204.129:38495 every 8 connection(s)
I20260812 06:17:34.257725 12649 heartbeater.cc:344] Connected to a master server at 127.11.204.190:44501
I20260812 06:17:34.257833 12649 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:34.258025 12649 heartbeater.cc:507] Master 127.11.204.190:44501 requested a full tablet report, sending...
I20260812 06:17:34.258618 12450 ts_manager.cc:194] Registered new tserver with Master: c57d536a0d704683a54989490ad60d0c (127.11.204.129:38495)
I20260812 06:17:34.258797 12082 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005528334s
I20260812 06:17:34.259447 12450 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51902
I20260812 06:17:34.265439 12450 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51904:
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:34.274078 12593 tablet_service.cc:1511] Processing CreateTablet for tablet 6d833ea510b2418ea37d62ad6326bc69 (DEFAULT_TABLE table=heavy-update-compaction-test [id=b4a392d67b5045a49e0f7921bbe1e274]), partition=
I20260812 06:17:34.274307 12593 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6d833ea510b2418ea37d62ad6326bc69. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:34.276095 12666 tablet_bootstrap.cc:492] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Bootstrap starting.
I20260812 06:17:34.277235 12666 tablet_bootstrap.cc:654] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:34.278185 12666 tablet_bootstrap.cc:492] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: No bootstrap required, opened a new log
I20260812 06:17:34.278260 12666 ts_tablet_manager.cc:1403] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:34.278620 12666 raft_consensus.cc:359] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c57d536a0d704683a54989490ad60d0c" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 38495 } }
I20260812 06:17:34.278718 12666 raft_consensus.cc:385] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:34.278743 12666 raft_consensus.cc:740] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: c57d536a0d704683a54989490ad60d0c, State: Initialized, Role: FOLLOWER
I20260812 06:17:34.278847 12666 consensus_queue.cc:260] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [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: "c57d536a0d704683a54989490ad60d0c" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 38495 } }
I20260812 06:17:34.278908 12666 raft_consensus.cc:399] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:34.278931 12666 raft_consensus.cc:493] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:34.278959 12666 raft_consensus.cc:3060] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:34.279875 12666 raft_consensus.cc:515] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c57d536a0d704683a54989490ad60d0c" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 38495 } }
I20260812 06:17:34.280025 12666 leader_election.cc:304] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [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: c57d536a0d704683a54989490ad60d0c; no voters: 
I20260812 06:17:34.280223 12666 leader_election.cc:290] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:34.280336 12668 raft_consensus.cc:2804] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:34.280591 12666 ts_tablet_manager.cc:1434] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:34.280624 12649 heartbeater.cc:499] Master 127.11.204.190:44501 was elected leader, sending a full tablet report...
I20260812 06:17:34.280645 12668 raft_consensus.cc:697] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 1 LEADER]: Becoming Leader. State: Replica: c57d536a0d704683a54989490ad60d0c, State: Running, Role: LEADER
I20260812 06:17:34.280826 12668 consensus_queue.cc:237] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [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: "c57d536a0d704683a54989490ad60d0c" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 38495 } }
I20260812 06:17:34.282141 12450 catalog_manager.cc:5719] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c reported cstate change: term changed from 0 to 1, leader changed from <none> to c57d536a0d704683a54989490ad60d0c (127.11.204.129). New cstate: current_term: 1 leader_uuid: "c57d536a0d704683a54989490ad60d0c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "c57d536a0d704683a54989490ad60d0c" member_type: VOTER last_known_addr { host: "127.11.204.129" port: 38495 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:34.337936 12082 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.009s	sys 0.014s
I20260812 06:17:34.503578 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69): perf score=23.023690
I20260812 06:17:34.687788 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.184s	user 0.119s	sys 0.064s Metrics: {"bytes_written":12799788,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":222,"dirs.run_wall_time_us":935,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":49211,"lbm_writes_lt_1ms":869,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":768,"update_count":1560}
I20260812 06:17:34.695748 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling LogGCOp(6d833ea510b2418ea37d62ad6326bc69): free 20290830 bytes of WAL
I20260812 06:17:34.695993 12559 log_reader.cc:385] T 6d833ea510b2418ea37d62ad6326bc69: removed 2 log segments from log reader
I20260812 06:17:34.696058 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000001 (ops 1-6)
I20260812 06:17:34.696143 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000002 (ops 7-10)
I20260812 06:17:34.701020 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: LogGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.005s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:17:34.701367 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69): 20513813 bytes on disk
I20260812 06:17:34.701752 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69) 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:17:34.702252 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:34.727042 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.025s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4020608,"delete_count":0,"lbm_write_time_us":5573,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:17:34.727504 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:34.736953 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3608,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:34.737340 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:34.922502 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.185s	user 0.102s	sys 0.082s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815796,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1386,"lbm_read_time_us":12883,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30538,"lbm_writes_lt_1ms":543,"mutex_wait_us":370,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":359,"threads_started":5,"update_count":2500}
I20260812 06:17:34.923089 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:34.983923 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.061s	user 0.030s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:34.984371 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:34.994848 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4185,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:34.995282 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:35.186761 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.191s	user 0.116s	sys 0.070s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":14150,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30344,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:17:35.187412 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:35.238364 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.051s	user 0.037s	sys 0.005s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19342,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.238857 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:35.261149 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.022s	user 0.006s	sys 0.015s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4513,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.261652 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:35.457643 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.196s	user 0.123s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":81,"lbm_read_time_us":12681,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31104,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:17:35.458457 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:35.506875 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.048s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21004,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:17:35.507689 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:35.546461 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.039s	user 0.014s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6059,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.546978 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:35.558552 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4588,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.559018 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:35.768260 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.209s	user 0.105s	sys 0.104s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":818,"lbm_read_time_us":15950,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32940,"lbm_writes_lt_1ms":643,"mutex_wait_us":290,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":3000}
I20260812 06:17:35.769016 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:35.827858 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.059s	user 0.029s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21006,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:35.828401 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:35.838827 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4136,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:35.839252 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:36.026764 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.187s	user 0.107s	sys 0.071s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":13160,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30497,"lbm_writes_lt_1ms":543,"mutex_wait_us":4,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:36.027390 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:36.081130 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.054s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21488,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.081660 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:36.093300 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.093989 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:36.131549 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.037s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":291,"dirs.run_wall_time_us":1562,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1633,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:36.132184 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling LogGCOp(6d833ea510b2418ea37d62ad6326bc69): free 129320449 bytes of WAL
I20260812 06:17:36.132408 12559 log_reader.cc:385] T 6d833ea510b2418ea37d62ad6326bc69: removed 13 log segments from log reader
I20260812 06:17:36.132454 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000003 (ops 11-15)
I20260812 06:17:36.132483 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000004 (ops 16-20)
I20260812 06:17:36.132562 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000005 (ops 21-25)
I20260812 06:17:36.132608 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000006 (ops 26-30)
I20260812 06:17:36.132655 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000007 (ops 31-34)
I20260812 06:17:36.132692 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000008 (ops 35-39)
I20260812 06:17:36.132733 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000009 (ops 40-44)
I20260812 06:17:36.132771 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000010 (ops 45-49)
I20260812 06:17:36.132808 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000011 (ops 50-54)
I20260812 06:17:36.132846 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000012 (ops 55-58)
I20260812 06:17:36.132884 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000013 (ops 59-63)
I20260812 06:17:36.132922 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000014 (ops 64-68)
I20260812 06:17:36.132962 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000015 (ops 69-73)
I20260812 06:17:36.162874 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: LogGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:36.163378 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69): 481 bytes on disk
I20260812 06:17:36.163882 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:17:36.164367 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=3.181125
I20260812 06:17:36.177552 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.013s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4380,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:36.177913 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:36.187224 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3681,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:36.187614 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:36.427891 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.240s	user 0.144s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020735,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":915,"lbm_read_time_us":16523,"lbm_reads_lt_1ms":774,"lbm_write_time_us":40616,"lbm_writes_lt_1ms":743,"mutex_wait_us":341,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14720,"thread_start_us":83,"threads_started":1,"update_count":3500}
I20260812 06:17:36.428629 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=18.063937
I20260812 06:17:36.482995 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.054s	user 0.034s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23480,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:36.483532 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:36.672484 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.189s	user 0.112s	sys 0.076s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24815566,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":751,"lbm_read_time_us":13465,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31896,"lbm_writes_lt_1ms":543,"mutex_wait_us":372,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2500}
I20260812 06:17:36.673219 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:36.734683 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.061s	user 0.034s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21373,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:36.735252 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:36.753033 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:36.753553 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:36.934588 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.181s	user 0.107s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":12459,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28969,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2500}
I20260812 06:17:36.935164 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:37.002919 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.068s	user 0.031s	sys 0.030s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23715,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.003425 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:37.019351 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6042,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.019987 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:37.209859 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.190s	user 0.103s	sys 0.077s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":203,"lbm_read_time_us":13620,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30892,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:37.210486 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:37.262622 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.052s	user 0.024s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18986,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.263116 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:37.274511 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.005s	sys 0.004s 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:17:37.275126 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:37.479678 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.204s	user 0.153s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":245,"lbm_read_time_us":14093,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33437,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:37.480365 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:37.533650 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.053s	user 0.027s	sys 0.018s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28008,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.534152 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:37.551585 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5969,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.552217 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:37.715991 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.164s	user 0.111s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":260,"lbm_read_time_us":9492,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31220,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:37.716498 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:37.766319 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.050s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19090,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:37.766916 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:37.777890 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4189,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:37.778360 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:37.815975 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.037s	user 0.035s	sys 0.001s Metrics: {"bytes_written":1316415,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1408,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1667,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:37.816686 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling LogGCOp(6d833ea510b2418ea37d62ad6326bc69): free 128867475 bytes of WAL
I20260812 06:17:37.816903 12559 log_reader.cc:385] T 6d833ea510b2418ea37d62ad6326bc69: removed 13 log segments from log reader
I20260812 06:17:37.816951 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000016 (ops 74-78)
I20260812 06:17:37.816979 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000017 (ops 79-82)
I20260812 06:17:37.817041 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000018 (ops 83-87)
I20260812 06:17:37.817098 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000019 (ops 88-92)
I20260812 06:17:37.817138 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000020 (ops 93-96)
I20260812 06:17:37.817180 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000021 (ops 97-101)
I20260812 06:17:37.817214 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000022 (ops 102-106)
I20260812 06:17:37.817255 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000023 (ops 107-111)
I20260812 06:17:37.817289 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000024 (ops 112-116)
I20260812 06:17:37.817332 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000025 (ops 117-121)
I20260812 06:17:37.817371 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000026 (ops 122-126)
I20260812 06:17:37.817402 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000027 (ops 127-130)
I20260812 06:17:37.817435 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000028 (ops 131-135)
I20260812 06:17:37.846786 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: LogGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:37.847146 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=6.157687
I20260812 06:17:37.877737 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.030s	user 0.017s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10824,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:17:37.878257 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling LogGCOp(6d833ea510b2418ea37d62ad6326bc69): free 12018006 bytes of WAL
I20260812 06:17:37.878475 12559 log_reader.cc:385] T 6d833ea510b2418ea37d62ad6326bc69: removed 1 log segments from log reader
I20260812 06:17:37.878572 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000029 (ops 136-140)
I20260812 06:17:37.881732 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: LogGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:37.882205 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69): 490 bytes on disk
I20260812 06:17:37.882699 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: UndoDeltaBlockGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:37.883221 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:38.120996 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.238s	user 0.153s	sys 0.081s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020628,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":917,"lbm_read_time_us":15077,"lbm_reads_lt_1ms":765,"lbm_write_time_us":38422,"lbm_writes_lt_1ms":743,"mutex_wait_us":362,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1920,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:17:38.123093 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=19.056125
I20260812 06:17:38.200299 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.077s	user 0.031s	sys 0.039s Metrics: {"bytes_written":20922556,"delete_count":0,"lbm_write_time_us":32705,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":511,"reinsert_count":0,"update_count":2550}
I20260812 06:17:38.200778 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=6.157687
I20260812 06:17:38.223646 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.023s	user 0.014s	sys 0.005s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9182,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:17:38.224313 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:38.453050 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.228s	user 0.154s	sys 0.074s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":33020509,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":839,"lbm_read_time_us":16312,"lbm_reads_lt_1ms":768,"lbm_write_time_us":41292,"lbm_writes_lt_1ms":743,"mutex_wait_us":351,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":3500}
I20260812 06:17:38.453665 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=19.056125
I20260812 06:17:38.517513 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.064s	user 0.040s	sys 0.021s Metrics: {"bytes_written":20922555,"delete_count":0,"lbm_write_time_us":28325,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:17:38.517949 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:38.528764 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4322,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.529170 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:38.538209 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3519,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:38.538626 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:38.728015 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.189s	user 0.149s	sys 0.040s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020614,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":106,"lbm_read_time_us":14769,"lbm_reads_lt_1ms":773,"lbm_write_time_us":39506,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":3500}
I20260812 06:17:38.730217 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:38.780267 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.050s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22656,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:38.780822 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:38.791493 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:38.791914 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:38.955433 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.163s	user 0.107s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":739,"lbm_read_time_us":10118,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30396,"lbm_writes_lt_1ms":543,"mutex_wait_us":372,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2500}
I20260812 06:17:38.956246 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:39.019533 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.063s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22245,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.020143 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:39.031267 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.031752 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:39.197114 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.165s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":10823,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29406,"lbm_writes_lt_1ms":543,"mutex_wait_us":284,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":2500}
I20260812 06:17:39.199632 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=14.095187
I20260812 06:17:39.255178 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.055s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19213,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:39.255851 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:39.267432 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.011s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4628,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.268043 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:39.300361 12082 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.962s	user 1.776s	sys 0.222s
I20260812 06:17:39.302244 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushMRSOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.034s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":29,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1331,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1720,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:39.302853 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling LogGCOp(6d833ea510b2418ea37d62ad6326bc69): free 120553636 bytes of WAL
I20260812 06:17:39.303066 12559 log_reader.cc:385] T 6d833ea510b2418ea37d62ad6326bc69: removed 12 log segments from log reader
I20260812 06:17:39.303112 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000030 (ops 141-145)
I20260812 06:17:39.303140 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000031 (ops 146-150)
I20260812 06:17:39.303184 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000032 (ops 151-155)
I20260812 06:17:39.303228 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000033 (ops 156-160)
I20260812 06:17:39.303279 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000034 (ops 161-164)
I20260812 06:17:39.303318 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000035 (ops 165-169)
I20260812 06:17:39.303354 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000036 (ops 170-174)
I20260812 06:17:39.303391 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000037 (ops 175-178)
I20260812 06:17:39.303429 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000038 (ops 179-183)
I20260812 06:17:39.303465 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000039 (ops 184-188)
I20260812 06:17:39.303503 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000040 (ops 189-193)
I20260812 06:17:39.303539 12559 log.cc:1079] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: Deleting log segment in path: /tmp/dist-test-task1tsBXo/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515448607242-12082-0/minicluster-data/ts-0-root/wals/6d833ea510b2418ea37d62ad6326bc69/wal-000000041 (ops 194-198)
I20260812 06:17:39.327116 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: LogGCOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:17:39.327595 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69): perf score=2.188937
I20260812 06:17:39.337422 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: FlushDeltaMemStoresOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:39.337821 12650 maintenance_manager.cc:419] P c57d536a0d704683a54989490ad60d0c: Scheduling MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69): perf score=1.000000
I20260812 06:17:39.367713 12082 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.067s	user 0.001s	sys 0.000s
I20260812 06:17:39.368247 12082 tablet_server.cc:179] TabletServer@127.11.204.129:0 shutting down...
I20260812 06:17:39.469946 12559 maintenance_manager.cc:643] P c57d536a0d704683a54989490ad60d0c: MajorDeltaCompactionOp(6d833ea510b2418ea37d62ad6326bc69) complete. Timing: real 0.132s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_hit":508,"cfile_cache_hit_bytes":21372975,"cfile_cache_miss":125,"cfile_cache_miss_bytes":7545239,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":364,"lbm_read_time_us":3872,"lbm_reads_lt_1ms":153,"lbm_write_time_us":30461,"lbm_writes_lt_1ms":643,"mutex_wait_us":94,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:17:39.471329 12082 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:39.471577 12082 tablet_replica.cc:333] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c: stopping tablet replica
I20260812 06:17:39.471737 12082 raft_consensus.cc:2243] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:39.471905 12082 raft_consensus.cc:2272] T 6d833ea510b2418ea37d62ad6326bc69 P c57d536a0d704683a54989490ad60d0c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:39.475040 12082 tablet_server.cc:196] TabletServer@127.11.204.129:0 shutdown complete.
I20260812 06:17:39.521867 12082 master.cc:562] Master@127.11.204.190:44501 shutting down...
I20260812 06:17:39.525677 12082 raft_consensus.cc:2243] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:39.525887 12082 raft_consensus.cc:2272] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:39.525979 12082 tablet_replica.cc:333] T 00000000000000000000000000000000 P c3bd4613156e4b189732760215c86879: stopping tablet replica
I20260812 06:17:39.538269 12082 master.cc:584] Master@127.11.204.190:44501 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5476 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11008 ms total)

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