[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:50.868347 31844 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.25.62:45057
I20260812 06:19:50.869484 31844 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:50.870121 31844 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:50.876478 31849 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:50.876583 31844 server_base.cc:1061] running on GCE node
W20260812 06:19:50.876771 31853 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:50.876528 31850 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:50.877323 31844 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:50.877467 31844 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:50.877517 31844 hybrid_clock.cc:648] HybridClock initialized: now 1786515590877514 us; error 0 us; skew 500 ppm
I20260812 06:19:50.879309 31844 webserver.cc:533] Webserver started at http://127.31.25.62:35895/ using document root <none> and password file <none>
I20260812 06:19:50.879954 31844 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:50.880024 31844 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:50.880290 31844 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:50.881976 31844 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/master-0-root/instance:
uuid: "5185729a931e459997fc8f5619cc32e4"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-mvvj"
I20260812 06:19:50.885648 31844 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:50.887892 31859 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:50.888965 31844 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:50.889070 31844 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/master-0-root
uuid: "5185729a931e459997fc8f5619cc32e4"
format_stamp: "Formatted at 2026-08-12 06:19:50 on dist-test-slave-mvvj"
I20260812 06:19:50.889202 31844 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:50.925427 31844 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:50.926185 31844 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:50.926476 31844 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:50.935662 31844 rpc_server.cc:307] RPC server started. Bound to: 127.31.25.62:45057
I20260812 06:19:50.935683 31922 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.25.62:45057 every 8 connection(s)
I20260812 06:19:50.938164 31923 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:50.943775 31923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: Bootstrap starting.
I20260812 06:19:50.946146 31923 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:50.947084 31923 log.cc:826] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:50.948907 31923 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: No bootstrap required, opened a new log
I20260812 06:19:50.951788 31923 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER }
I20260812 06:19:50.952056 31923 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:50.952165 31923 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5185729a931e459997fc8f5619cc32e4, State: Initialized, Role: FOLLOWER
I20260812 06:19:50.952778 31923 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [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: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER }
I20260812 06:19:50.952960 31923 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:50.953047 31923 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:50.953166 31923 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:50.953984 31923 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER }
I20260812 06:19:50.954435 31923 leader_election.cc:304] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [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: 5185729a931e459997fc8f5619cc32e4; no voters: 
I20260812 06:19:50.954768 31923 leader_election.cc:290] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:50.954931 31926 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:50.955217 31926 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 1 LEADER]: Becoming Leader. State: Replica: 5185729a931e459997fc8f5619cc32e4, State: Running, Role: LEADER
I20260812 06:19:50.955607 31926 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [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: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER }
I20260812 06:19:50.955856 31923 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:50.957712 31927 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5185729a931e459997fc8f5619cc32e4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER } }
I20260812 06:19:50.957664 31928 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5185729a931e459997fc8f5619cc32e4. Latest consensus state: current_term: 1 leader_uuid: "5185729a931e459997fc8f5619cc32e4" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5185729a931e459997fc8f5619cc32e4" member_type: VOTER } }
I20260812 06:19:50.957813 31927 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:50.957813 31928 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:50.958175 31940 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:50.958292 31844 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:50.960454 31940 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:50.965065 31940 catalog_manager.cc:1383] Generated new cluster ID: 98429260fb834966a335045213e4ede8
I20260812 06:19:50.965144 31940 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:50.989568 31940 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:50.990883 31940 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:51.009603 31940 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: Generated new TSK 0
I20260812 06:19:51.010399 31940 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:51.023268 31844 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:51.026381 31949 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:51.026472 31947 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:51.026386 31946 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:51.027174 31844 server_base.cc:1061] running on GCE node
I20260812 06:19:51.027376 31844 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:51.027424 31844 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:51.027447 31844 hybrid_clock.cc:648] HybridClock initialized: now 1786515591027447 us; error 0 us; skew 500 ppm
I20260812 06:19:51.028515 31844 webserver.cc:533] Webserver started at http://127.31.25.1:41421/ using document root <none> and password file <none>
I20260812 06:19:51.028688 31844 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:51.028751 31844 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:51.028828 31844 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:51.029273 31844 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/instance:
uuid: "2b3fccc81ed74db5a718fed15cf266c0"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-mvvj"
I20260812 06:19:51.031152 31844 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:51.032334 31956 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.032658 31844 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:51.032727 31844 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root
uuid: "2b3fccc81ed74db5a718fed15cf266c0"
format_stamp: "Formatted at 2026-08-12 06:19:51 on dist-test-slave-mvvj"
I20260812 06:19:51.032821 31844 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:51.044625 31844 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:51.045156 31844 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:51.045688 31844 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:51.046605 31844 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:51.046657 31844 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.046728 31844 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:51.046766 31844 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:51.053696 31844 rpc_server.cc:307] RPC server started. Bound to: 127.31.25.1:33111
I20260812 06:19:51.053903 32025 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.25.1:33111 every 8 connection(s)
I20260812 06:19:51.069859 32027 heartbeater.cc:344] Connected to a master server at 127.31.25.62:45057
I20260812 06:19:51.070127 32027 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:51.070667 32027 heartbeater.cc:507] Master 127.31.25.62:45057 requested a full tablet report, sending...
I20260812 06:19:51.072172 31879 ts_manager.cc:194] Registered new tserver with Master: 2b3fccc81ed74db5a718fed15cf266c0 (127.31.25.1:33111)
I20260812 06:19:51.072674 31844 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018273742s
I20260812 06:19:51.073751 31879 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41554
I20260812 06:19:51.082926 31879 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41566:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:51.097939 31986 tablet_service.cc:1511] Processing CreateTablet for tablet 9594eeeeb5b340d6b7734969dd4c516d (DEFAULT_TABLE table=heavy-update-compaction-test [id=6f8fa6b978914e75a728511c9a529f1d]), partition=
I20260812 06:19:51.098464 31986 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 9594eeeeb5b340d6b7734969dd4c516d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:51.101037 32042 tablet_bootstrap.cc:492] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Bootstrap starting.
I20260812 06:19:51.102614 32042 tablet_bootstrap.cc:654] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:51.103744 32042 tablet_bootstrap.cc:492] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: No bootstrap required, opened a new log
I20260812 06:19:51.103832 32042 ts_tablet_manager.cc:1403] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:51.104357 32042 raft_consensus.cc:359] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b3fccc81ed74db5a718fed15cf266c0" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 33111 } }
I20260812 06:19:51.104460 32042 raft_consensus.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:51.104483 32042 raft_consensus.cc:740] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2b3fccc81ed74db5a718fed15cf266c0, State: Initialized, Role: FOLLOWER
I20260812 06:19:51.104686 32042 consensus_queue.cc:260] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [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: "2b3fccc81ed74db5a718fed15cf266c0" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 33111 } }
I20260812 06:19:51.104763 32042 raft_consensus.cc:399] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:51.104825 32042 raft_consensus.cc:493] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:51.104875 32042 raft_consensus.cc:3060] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:51.105626 32042 raft_consensus.cc:515] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b3fccc81ed74db5a718fed15cf266c0" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 33111 } }
I20260812 06:19:51.105773 32042 leader_election.cc:304] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [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: 2b3fccc81ed74db5a718fed15cf266c0; no voters: 
I20260812 06:19:51.106019 32042 leader_election.cc:290] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:51.106139 32044 raft_consensus.cc:2804] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:51.106352 32044 raft_consensus.cc:697] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 1 LEADER]: Becoming Leader. State: Replica: 2b3fccc81ed74db5a718fed15cf266c0, State: Running, Role: LEADER
I20260812 06:19:51.106510 32042 ts_tablet_manager.cc:1434] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:51.106559 32044 consensus_queue.cc:237] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [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: "2b3fccc81ed74db5a718fed15cf266c0" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 33111 } }
I20260812 06:19:51.106980 32027 heartbeater.cc:499] Master 127.31.25.62:45057 was elected leader, sending a full tablet report...
I20260812 06:19:51.109740 31879 catalog_manager.cc:5719] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2b3fccc81ed74db5a718fed15cf266c0 (127.31.25.1). New cstate: current_term: 1 leader_uuid: "2b3fccc81ed74db5a718fed15cf266c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2b3fccc81ed74db5a718fed15cf266c0" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 33111 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:51.175347 31844 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.022s	sys 0.004s
I20260812 06:19:51.304888 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=19.054940
I20260812 06:19:51.468042 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.163s	user 0.136s	sys 0.024s Metrics: {"bytes_written":8615323,"cfile_init":1,"compiler_manager_pool.queue_time_us":237,"delete_count":0,"dirs.queue_time_us":85,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":989,"drs_written":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40755,"lbm_writes_lt_1ms":667,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":136,"threads_started":1,"update_count":1050}
I20260812 06:19:51.469319 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling LogGCOp(9594eeeeb5b340d6b7734969dd4c516d): free 20743880 bytes of WAL
I20260812 06:19:51.469645 31962 log_reader.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d: removed 2 log segments from log reader
I20260812 06:19:51.469712 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000001 (ops 1-6)
I20260812 06:19:51.469782 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000002 (ops 7-11)
I20260812 06:19:51.475579 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: LogGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.006s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:51.476047 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:51.494480 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.018s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6277,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:51.494990 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d): 16411392 bytes on disk
I20260812 06:19:51.495602 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:19:51.496125 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:51.621383 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.125s	user 0.081s	sys 0.033s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569856,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":962,"lbm_read_time_us":6399,"lbm_reads_lt_1ms":364,"lbm_write_time_us":20891,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":289,"threads_started":5,"update_count":1500}
I20260812 06:19:51.621905 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:51.671411 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.049s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17197,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.671959 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:51.682415 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3888,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.683092 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:51.812115 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.129s	user 0.100s	sys 0.026s 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":217,"lbm_read_time_us":9476,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23159,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:19:51.812659 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:51.869705 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.057s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15293,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:51.870271 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:51.882258 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:51.882740 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.042332 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.159s	user 0.121s	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":509,"lbm_read_time_us":10141,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26789,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:52.042884 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:52.091578 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.048s	user 0.030s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21054,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.092104 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:52.102702 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.103299 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.235904 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.132s	user 0.121s	sys 0.011s 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":1340,"lbm_read_time_us":9849,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22975,"lbm_writes_lt_1ms":443,"mutex_wait_us":346,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2000}
I20260812 06:19:52.236548 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:52.279301 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.043s	user 0.024s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15141,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.279966 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:52.290943 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4028,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.291538 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.418641 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.127s	user 0.110s	sys 0.015s 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":384,"lbm_read_time_us":10145,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":471,"lbm_write_time_us":23375,"lbm_writes_lt_1ms":443,"mutex_wait_us":78,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:19:52.419335 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:52.462029 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.043s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.462730 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:52.473515 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4128,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.473999 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.630309 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.156s	user 0.101s	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":211,"lbm_read_time_us":11275,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25869,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2000}
I20260812 06:19:52.630940 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:52.665827 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.035s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12926,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.666841 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.777915 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.111s	user 0.086s	sys 0.024s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569747,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":505,"lbm_read_time_us":7170,"lbm_reads_lt_1ms":363,"lbm_write_time_us":20582,"lbm_writes_lt_1ms":343,"mutex_wait_us":60,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:19:52.778460 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:52.810724 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.032s	user 0.029s	sys 0.000s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":13852,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:52.811298 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:52.849172 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.038s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1409,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1604,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:52.850237 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=3.181125
I20260812 06:19:52.863897 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.013s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:52.864346 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling LogGCOp(9594eeeeb5b340d6b7734969dd4c516d): free 121006437 bytes of WAL
I20260812 06:19:52.864573 31962 log_reader.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d: removed 12 log segments from log reader
I20260812 06:19:52.864619 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000003 (ops 12-16)
I20260812 06:19:52.864646 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000004 (ops 17-20)
I20260812 06:19:52.864708 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000005 (ops 21-25)
I20260812 06:19:52.864742 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000006 (ops 26-30)
I20260812 06:19:52.864777 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000007 (ops 31-35)
I20260812 06:19:52.864807 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000008 (ops 36-40)
I20260812 06:19:52.864845 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000009 (ops 41-45)
I20260812 06:19:52.864882 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000010 (ops 46-50)
I20260812 06:19:52.864918 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000011 (ops 51-55)
I20260812 06:19:52.864959 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000012 (ops 56-60)
I20260812 06:19:52.864998 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000013 (ops 61-65)
I20260812 06:19:52.865036 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000014 (ops 66-70)
I20260812 06:19:52.889879 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: LogGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:52.890425 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:52.908394 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.018s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3853,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:52.908859 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:52.918979 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:52.919467 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d): 472 bytes on disk
I20260812 06:19:52.919970 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:52.920442 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:53.100214 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.180s	user 0.121s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":709,"lbm_read_time_us":11062,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33513,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15872,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:19:53.101392 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:53.155675 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.054s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23406,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.156414 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:53.173333 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.017s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5467,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.173856 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:53.320848 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.147s	user 0.098s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":330,"lbm_read_time_us":8344,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26738,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:19:53.321485 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:53.375053 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.053s	user 0.028s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23015,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.375581 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:53.534201 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.158s	user 0.089s	sys 0.063s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":275,"lbm_read_time_us":8713,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25942,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:19:53.534878 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:53.588713 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.054s	user 0.034s	sys 0.019s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":24573,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.589267 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:53.602260 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4393,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.602754 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:53.793627 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.191s	user 0.110s	sys 0.067s 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":193,"lbm_read_time_us":12003,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30893,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:53.794185 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:53.844374 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.050s	user 0.028s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21611,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:53.845016 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:53.856966 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:53.857513 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:54.008674 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.151s	user 0.119s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":75,"lbm_read_time_us":9304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30368,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23424,"update_count":2500}
I20260812 06:19:54.009394 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=10.126437
I20260812 06:19:54.053913 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.044s	user 0.027s	sys 0.015s Metrics: {"bytes_written":12348515,"delete_count":0,"lbm_write_time_us":15917,"lbm_writes_lt_1ms":304,"reinsert_count":0,"update_count":1505}
I20260812 06:19:54.054590 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.071384 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.017s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":6373,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:54.072065 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:54.198608 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.126s	user 0.095s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1005,"lbm_read_time_us":7431,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24434,"lbm_writes_lt_1ms":443,"mutex_wait_us":358,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.199354 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=11.118625
I20260812 06:19:54.235499 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.036s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15903,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:54.236132 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.253360 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.017s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4734,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.253952 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:54.294138 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.040s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1448,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1872,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:54.294965 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=3.181125
I20260812 06:19:54.309026 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4985,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:54.309495 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling LogGCOp(9594eeeeb5b340d6b7734969dd4c516d): free 120100276 bytes of WAL
I20260812 06:19:54.309713 31962 log_reader.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d: removed 12 log segments from log reader
I20260812 06:19:54.309754 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000015 (ops 71-74)
I20260812 06:19:54.309783 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000016 (ops 75-79)
I20260812 06:19:54.309841 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000017 (ops 80-84)
I20260812 06:19:54.309883 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000018 (ops 85-89)
I20260812 06:19:54.309921 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000019 (ops 90-94)
I20260812 06:19:54.309958 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000020 (ops 95-99)
I20260812 06:19:54.310002 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000021 (ops 100-104)
I20260812 06:19:54.310041 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000022 (ops 105-108)
I20260812 06:19:54.310078 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000023 (ops 109-113)
I20260812 06:19:54.310117 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000024 (ops 114-118)
I20260812 06:19:54.310153 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000025 (ops 119-122)
I20260812 06:19:54.310191 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000026 (ops 123-127)
I20260812 06:19:54.335492 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: LogGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:19:54.336025 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d): 473 bytes on disk
I20260812 06:19:54.336531 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: UndoDeltaBlockGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:54.337096 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.349743 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.012s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3965,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.350262 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling LogGCOp(9594eeeeb5b340d6b7734969dd4c516d): free 12018000 bytes of WAL
I20260812 06:19:54.350468 31962 log_reader.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d: removed 1 log segments from log reader
I20260812 06:19:54.350514 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000027 (ops 128-132)
I20260812 06:19:54.352771 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: LogGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:54.353091 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.363350 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:54.364153 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:54.544785 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.180s	user 0.164s	sys 0.016s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":543,"lbm_read_time_us":12245,"lbm_reads_lt_1ms":775,"lbm_write_time_us":35366,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":95,"threads_started":1,"update_count":3500}
I20260812 06:19:54.545542 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:54.596480 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.051s	user 0.038s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.597059 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.610764 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5255,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.611217 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:54.801627 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.190s	user 0.148s	sys 0.012s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":869,"lbm_read_time_us":11086,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33829,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:54.802480 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:54.866225 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.063s	user 0.027s	sys 0.025s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24646,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:54.866763 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:54.877172 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:54.877862 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:55.064363 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.186s	user 0.121s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":152,"lbm_read_time_us":13060,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29747,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:55.065152 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:55.117321 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.052s	user 0.039s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21410,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.117810 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:55.131352 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4652,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.132110 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:55.319891 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.188s	user 0.125s	sys 0.053s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":400,"lbm_read_time_us":13515,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30541,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:55.320595 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:55.379050 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.058s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":20723,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.379881 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:55.390626 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4180,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.391285 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:55.580961 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.189s	user 0.124s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":11888,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30377,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":85760,"update_count":2500}
I20260812 06:19:55.581599 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:55.639371 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.058s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19058,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.640101 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:55.651823 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.012s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.652343 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:55.849371 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.197s	user 0.113s	sys 0.076s 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":109,"lbm_read_time_us":12638,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31368,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2500}
I20260812 06:19:55.850149 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=14.095187
I20260812 06:19:55.899024 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.049s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19875,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:55.899600 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:55.924417 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.025s	user 0.013s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5663,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:55.925274 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:55.966365 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushMRSOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.041s	user 0.033s	sys 0.001s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":419,"dirs.run_wall_time_us":1772,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2360,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:55.967089 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling LogGCOp(9594eeeeb5b340d6b7734969dd4c516d): free 124710562 bytes of WAL
I20260812 06:19:55.967314 31962 log_reader.cc:385] T 9594eeeeb5b340d6b7734969dd4c516d: removed 12 log segments from log reader
I20260812 06:19:55.967360 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000028 (ops 133-137)
I20260812 06:19:55.967386 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000029 (ops 138-142)
I20260812 06:19:55.967446 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000030 (ops 143-147)
I20260812 06:19:55.967499 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000031 (ops 148-152)
I20260812 06:19:55.967538 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000032 (ops 153-157)
I20260812 06:19:55.967556 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000033 (ops 158-162)
I20260812 06:19:55.967614 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000034 (ops 163-167)
I20260812 06:19:55.967653 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000035 (ops 168-172)
I20260812 06:19:55.967694 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000036 (ops 173-177)
I20260812 06:19:55.967732 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000037 (ops 178-182)
I20260812 06:19:55.967772 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000038 (ops 183-187)
I20260812 06:19:55.967811 31962 log.cc:1079] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/9594eeeeb5b340d6b7734969dd4c516d/wal-000000039 (ops 188-192)
I20260812 06:19:55.994514 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: LogGCOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.027s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:19:55.994987 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=3.181125
I20260812 06:19:56.012817 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.018s	user 0.004s	sys 0.007s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:56.013504 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=2.188937
I20260812 06:19:56.024037 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: FlushDeltaMemStoresOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:56.024729 32028 maintenance_manager.cc:419] P 2b3fccc81ed74db5a718fed15cf266c0: Scheduling MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d): perf score=1.000000
I20260812 06:19:56.110544 31844 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.935s	user 1.817s	sys 0.151s
I20260812 06:19:56.222973 31844 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.001s	sys 0.000s
I20260812 06:19:56.223676 31844 tablet_server.cc:179] TabletServer@127.31.25.1:0 shutting down...
I20260812 06:19:56.252053 31962 maintenance_manager.cc:643] P 2b3fccc81ed74db5a718fed15cf266c0: MajorDeltaCompactionOp(9594eeeeb5b340d6b7734969dd4c516d) complete. Timing: real 0.227s	user 0.136s	sys 0.091s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1063,"lbm_read_time_us":14480,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36976,"lbm_writes_lt_1ms":743,"mutex_wait_us":29,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":20224,"thread_start_us":93,"threads_started":1,"update_count":3500}
I20260812 06:19:56.254194 31844 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:56.254686 31844 tablet_replica.cc:333] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0: stopping tablet replica
I20260812 06:19:56.254957 31844 raft_consensus.cc:2243] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.255223 31844 raft_consensus.cc:2272] T 9594eeeeb5b340d6b7734969dd4c516d P 2b3fccc81ed74db5a718fed15cf266c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.272346 31844 tablet_server.cc:196] TabletServer@127.31.25.1:0 shutdown complete.
I20260812 06:19:56.312027 31844 master.cc:562] Master@127.31.25.62:45057 shutting down...
I20260812 06:19:56.316991 31844 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:56.317224 31844 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:56.317317 31844 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5185729a931e459997fc8f5619cc32e4: stopping tablet replica
I20260812 06:19:56.330237 31844 master.cc:584] Master@127.31.25.62:45057 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5550 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:56.419387 31844 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.31.25.62:35181
I20260812 06:19:56.419796 31844 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.422456 32068 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:56.422423 32066 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.422629 31844 server_base.cc:1061] running on GCE node
W20260812 06:19:56.422657 32065 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.422956 31844 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.423022 31844 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:56.423048 31844 hybrid_clock.cc:648] HybridClock initialized: now 1786515596423047 us; error 0 us; skew 500 ppm
I20260812 06:19:56.424001 31844 webserver.cc:533] Webserver started at http://127.31.25.62:46283/ using document root <none> and password file <none>
I20260812 06:19:56.424187 31844 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.424252 31844 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.424333 31844 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.424746 31844 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/master-0-root/instance:
uuid: "0012963fa72145d180094d72dfc147ac"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-mvvj"
I20260812 06:19:56.426292 31844 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:56.427229 32073 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.427486 31844 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:56.427590 31844 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/master-0-root
uuid: "0012963fa72145d180094d72dfc147ac"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-mvvj"
I20260812 06:19:56.427681 31844 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:56.437318 31844 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.437757 31844 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.442298 31844 rpc_server.cc:307] RPC server started. Bound to: 127.31.25.62:35181
I20260812 06:19:56.443722 32130 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.25.62:35181 every 8 connection(s)
I20260812 06:19:56.445295 32131 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:56.455696 32131 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac: Bootstrap starting.
I20260812 06:19:56.456597 32131 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.457727 32131 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac: No bootstrap required, opened a new log
I20260812 06:19:56.458097 32131 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0012963fa72145d180094d72dfc147ac" member_type: VOTER }
I20260812 06:19:56.458191 32131 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.458213 32131 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0012963fa72145d180094d72dfc147ac, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.458379 32131 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [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: "0012963fa72145d180094d72dfc147ac" member_type: VOTER }
I20260812 06:19:56.458477 32131 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.458510 32131 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.458541 32131 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.459228 32131 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0012963fa72145d180094d72dfc147ac" member_type: VOTER }
I20260812 06:19:56.459349 32131 leader_election.cc:304] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [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: 0012963fa72145d180094d72dfc147ac; no voters: 
I20260812 06:19:56.459522 32131 leader_election.cc:290] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.459695 32135 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.459918 32135 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 1 LEADER]: Becoming Leader. State: Replica: 0012963fa72145d180094d72dfc147ac, State: Running, Role: LEADER
I20260812 06:19:56.460083 32131 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:56.460085 32135 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [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: "0012963fa72145d180094d72dfc147ac" member_type: VOTER }
I20260812 06:19:56.460602 32137 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0012963fa72145d180094d72dfc147ac. Latest consensus state: current_term: 1 leader_uuid: "0012963fa72145d180094d72dfc147ac" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0012963fa72145d180094d72dfc147ac" member_type: VOTER } }
I20260812 06:19:56.460695 32137 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.460582 32136 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0012963fa72145d180094d72dfc147ac" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0012963fa72145d180094d72dfc147ac" member_type: VOTER } }
I20260812 06:19:56.460747 32136 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.461246 32139 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:56.462179 32139 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:56.462404 31844 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:56.464174 32139 catalog_manager.cc:1383] Generated new cluster ID: 716d7c5692774cfca4057e3c61ce9296
I20260812 06:19:56.464229 32139 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:56.496264 32139 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:56.496899 32139 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:56.500859 32139 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac: Generated new TSK 0
I20260812 06:19:56.501037 32139 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:56.527166 31844 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.529609 32157 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:56.529594 32158 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:56.529594 32160 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.530321 31844 server_base.cc:1061] running on GCE node
I20260812 06:19:56.530556 31844 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.530601 31844 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:56.530618 31844 hybrid_clock.cc:648] HybridClock initialized: now 1786515596530618 us; error 0 us; skew 500 ppm
I20260812 06:19:56.531662 31844 webserver.cc:533] Webserver started at http://127.31.25.1:39771/ using document root <none> and password file <none>
I20260812 06:19:56.531904 31844 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.531993 31844 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.532079 31844 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.532519 31844 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/instance:
uuid: "e82872b8260c4cdc8075848082492b73"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-mvvj"
I20260812 06:19:56.534198 31844 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:56.535333 32165 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.535735 31844 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:56.535809 31844 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root
uuid: "e82872b8260c4cdc8075848082492b73"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-mvvj"
I20260812 06:19:56.535934 31844 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:56.545452 31844 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.545881 31844 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.546202 31844 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:56.546706 31844 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:56.546746 31844 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.546809 31844 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:56.546850 31844 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.551796 31844 rpc_server.cc:307] RPC server started. Bound to: 127.31.25.1:34147
I20260812 06:19:56.552582 32233 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.31.25.1:34147 every 8 connection(s)
I20260812 06:19:56.562004 32234 heartbeater.cc:344] Connected to a master server at 127.31.25.62:35181
I20260812 06:19:56.562188 32234 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:56.562472 32234 heartbeater.cc:507] Master 127.31.25.62:35181 requested a full tablet report, sending...
I20260812 06:19:56.563329 32091 ts_manager.cc:194] Registered new tserver with Master: e82872b8260c4cdc8075848082492b73 (127.31.25.1:34147)
I20260812 06:19:56.563885 31844 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011226082s
I20260812 06:19:56.564498 32091 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50356
I20260812 06:19:56.571741 32091 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50362:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:56.581444 32197 tablet_service.cc:1511] Processing CreateTablet for tablet abee1a72c0854ad69b098bfed19f29bc (DEFAULT_TABLE table=heavy-update-compaction-test [id=330852a179a64dafaa1e00c875b68160]), partition=
I20260812 06:19:56.581769 32197 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet abee1a72c0854ad69b098bfed19f29bc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:56.584098 32248 tablet_bootstrap.cc:492] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Bootstrap starting.
I20260812 06:19:56.585029 32248 tablet_bootstrap.cc:654] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.586331 32248 tablet_bootstrap.cc:492] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: No bootstrap required, opened a new log
I20260812 06:19:56.586544 32248 ts_tablet_manager.cc:1403] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:56.587152 32248 raft_consensus.cc:359] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e82872b8260c4cdc8075848082492b73" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 34147 } }
I20260812 06:19:56.587288 32248 raft_consensus.cc:385] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.587352 32248 raft_consensus.cc:740] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e82872b8260c4cdc8075848082492b73, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.587569 32248 consensus_queue.cc:260] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [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: "e82872b8260c4cdc8075848082492b73" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 34147 } }
I20260812 06:19:56.587658 32248 raft_consensus.cc:399] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.587724 32248 raft_consensus.cc:493] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.587793 32248 raft_consensus.cc:3060] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.588662 32248 raft_consensus.cc:515] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e82872b8260c4cdc8075848082492b73" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 34147 } }
I20260812 06:19:56.588829 32248 leader_election.cc:304] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [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: e82872b8260c4cdc8075848082492b73; no voters: 
I20260812 06:19:56.589100 32248 leader_election.cc:290] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.589236 32250 raft_consensus.cc:2804] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.589519 32248 ts_tablet_manager.cc:1434] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:56.589501 32250 raft_consensus.cc:697] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 1 LEADER]: Becoming Leader. State: Replica: e82872b8260c4cdc8075848082492b73, State: Running, Role: LEADER
I20260812 06:19:56.589584 32234 heartbeater.cc:499] Master 127.31.25.62:35181 was elected leader, sending a full tablet report...
I20260812 06:19:56.589699 32250 consensus_queue.cc:237] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [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: "e82872b8260c4cdc8075848082492b73" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 34147 } }
I20260812 06:19:56.591126 32091 catalog_manager.cc:5719] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 reported cstate change: term changed from 0 to 1, leader changed from <none> to e82872b8260c4cdc8075848082492b73 (127.31.25.1). New cstate: current_term: 1 leader_uuid: "e82872b8260c4cdc8075848082492b73" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e82872b8260c4cdc8075848082492b73" member_type: VOTER last_known_addr { host: "127.31.25.1" port: 34147 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:56.651743 31844 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.018s	sys 0.006s
I20260812 06:19:56.803431 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc): perf score=19.054940
I20260812 06:19:56.960701 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.157s	user 0.136s	sys 0.020s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":286,"dirs.run_wall_time_us":1097,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39874,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:19:56.961472 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling LogGCOp(abee1a72c0854ad69b098bfed19f29bc): free 20743880 bytes of WAL
I20260812 06:19:56.961826 32171 log_reader.cc:385] T abee1a72c0854ad69b098bfed19f29bc: removed 2 log segments from log reader
I20260812 06:19:56.961875 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000001 (ops 1-6)
I20260812 06:19:56.961906 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000002 (ops 7-11)
I20260812 06:19:56.966358 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: LogGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:56.966792 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:56.982214 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5476,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:56.982738 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc): 16411394 bytes on disk
I20260812 06:19:56.983275 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:19:56.983932 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:57.140286 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.156s	user 0.111s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":516,"lbm_read_time_us":10911,"lbm_reads_lt_1ms":460,"lbm_write_time_us":23953,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":112256,"thread_start_us":320,"threads_started":5,"update_count":2000}
I20260812 06:19:57.140885 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:19:57.209405 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.068s	user 0.049s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30708,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.209962 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:57.220362 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.220856 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:57.399808 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.179s	user 0.126s	sys 0.052s 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":802,"lbm_read_time_us":12796,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30276,"lbm_writes_lt_1ms":543,"mutex_wait_us":377,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:19:57.400429 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=11.118625
I20260812 06:19:57.434563 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":13045920,"delete_count":0,"lbm_write_time_us":14207,"lbm_writes_lt_1ms":321,"reinsert_count":0,"update_count":1590}
I20260812 06:19:57.435263 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:57.465186 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.030s	user 0.006s	sys 0.009s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4969,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:19:57.465746 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:57.480396 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.014s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5577,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.480875 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:57.647164 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.166s	user 0.095s	sys 0.068s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774783,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":538,"lbm_read_time_us":11703,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28374,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.647953 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:19:57.703228 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.055s	user 0.047s	sys 0.005s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24877,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.703889 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:57.714638 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4031,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.715127 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:57.890692 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.175s	user 0.110s	sys 0.063s 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":147,"lbm_read_time_us":12695,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29994,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:57.891215 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:19:57.953961 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.062s	user 0.034s	sys 0.025s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":23982,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:57.954532 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:57.966795 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4204,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.967489 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:58.145680 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.178s	user 0.126s	sys 0.052s 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":411,"lbm_read_time_us":13126,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28979,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":2500}
I20260812 06:19:58.146466 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:19:58.209722 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.063s	user 0.023s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20206,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.210312 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:58.221302 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.221802 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:58.255028 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":110,"dirs.run_cpu_time_us":317,"dirs.run_wall_time_us":1816,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1417,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:58.255738 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:58.431535 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.176s	user 0.111s	sys 0.064s 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":404,"lbm_read_time_us":11423,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29367,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10624,"update_count":2500}
I20260812 06:19:58.432507 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling LogGCOp(abee1a72c0854ad69b098bfed19f29bc): free 120553333 bytes of WAL
I20260812 06:19:58.432835 32171 log_reader.cc:385] T abee1a72c0854ad69b098bfed19f29bc: removed 12 log segments from log reader
I20260812 06:19:58.432899 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000003 (ops 12-16)
I20260812 06:19:58.433017 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000004 (ops 17-21)
I20260812 06:19:58.433073 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000005 (ops 22-26)
I20260812 06:19:58.433151 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000006 (ops 27-31)
I20260812 06:19:58.433202 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000007 (ops 32-36)
I20260812 06:19:58.433252 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000008 (ops 37-40)
I20260812 06:19:58.433300 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000009 (ops 41-45)
I20260812 06:19:58.433377 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000010 (ops 46-50)
I20260812 06:19:58.433426 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000011 (ops 51-55)
I20260812 06:19:58.433482 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000012 (ops 56-60)
I20260812 06:19:58.433531 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000013 (ops 61-64)
I20260812 06:19:58.433579 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000014 (ops 65-69)
I20260812 06:19:58.459656 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: LogGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:58.460150 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc): 462 bytes on disk
I20260812 06:19:58.460671 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc) 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:19:58.461246 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=18.063937
I20260812 06:19:58.530862 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.069s	user 0.027s	sys 0.039s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26988,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:58.531507 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:58.547730 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.016s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.548257 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:58.558872 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.559401 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:58.796792 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.237s	user 0.154s	sys 0.083s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979636,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1111,"lbm_read_time_us":15705,"lbm_reads_lt_1ms":773,"lbm_write_time_us":38655,"lbm_writes_lt_1ms":743,"mutex_wait_us":31,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":392704,"update_count":3500}
I20260812 06:19:58.797343 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=18.063937
I20260812 06:19:58.872428 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.075s	user 0.036s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":30315,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":500,"reinsert_count":0,"update_count":2500}
I20260812 06:19:58.872920 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:58.883620 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4061,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.884244 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:59.108893 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.224s	user 0.170s	sys 0.044s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1000,"lbm_read_time_us":14151,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34539,"lbm_writes_lt_1ms":643,"mutex_wait_us":372,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:19:59.109566 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=18.063937
I20260812 06:19:59.183475 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.074s	user 0.034s	sys 0.025s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28060,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.184060 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:59.200346 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5990,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.201092 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:59.434427 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.233s	user 0.130s	sys 0.096s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":485,"lbm_read_time_us":16466,"lbm_reads_lt_1ms":672,"lbm_write_time_us":39655,"lbm_writes_lt_1ms":643,"mutex_wait_us":88,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":19712,"update_count":3000}
I20260812 06:19:59.435231 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=16.079562
I20260812 06:19:59.490025 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.055s	user 0.037s	sys 0.015s Metrics: {"bytes_written":17722676,"delete_count":0,"lbm_write_time_us":24051,"lbm_writes_lt_1ms":435,"reinsert_count":0,"update_count":2160}
I20260812 06:19:59.490494 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.196750
I20260812 06:19:59.501684 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3159084,"delete_count":0,"lbm_write_time_us":3179,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:19:59.502214 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:59.667747 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.165s	user 0.100s	sys 0.065s Metrics: {"cfile_cache_miss":541,"cfile_cache_miss_bytes":25143888,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":646,"lbm_read_time_us":12448,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26488,"lbm_writes_lt_1ms":552,"mutex_wait_us":295,"peak_mem_usage":63485215,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2545}
I20260812 06:19:59.668342 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:19:59.728439 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.060s	user 0.028s	sys 0.030s Metrics: {"bytes_written":16040690,"delete_count":0,"lbm_write_time_us":21907,"lbm_writes_lt_1ms":394,"reinsert_count":0,"update_count":1955}
I20260812 06:19:59.729112 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:59.740800 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.741331 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:19:59.783617 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.042s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":120,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1493,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:59.784400 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling LogGCOp(abee1a72c0854ad69b098bfed19f29bc): free 120553440 bytes of WAL
I20260812 06:19:59.784662 32171 log_reader.cc:385] T abee1a72c0854ad69b098bfed19f29bc: removed 12 log segments from log reader
I20260812 06:19:59.784709 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000015 (ops 70-74)
I20260812 06:19:59.784740 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000016 (ops 75-78)
I20260812 06:19:59.784811 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000017 (ops 79-83)
I20260812 06:19:59.784849 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000018 (ops 84-88)
I20260812 06:19:59.784895 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000019 (ops 89-92)
I20260812 06:19:59.784972 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000020 (ops 93-97)
I20260812 06:19:59.785028 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000021 (ops 98-102)
I20260812 06:19:59.785073 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000022 (ops 103-107)
I20260812 06:19:59.785102 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000023 (ops 108-112)
I20260812 06:19:59.785148 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000024 (ops 113-117)
I20260812 06:19:59.785192 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000025 (ops 118-122)
I20260812 06:19:59.785236 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000026 (ops 123-127)
I20260812 06:19:59.814335 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: LogGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:59.814831 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc): 462 bytes on disk
I20260812 06:19:59.815474 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4}
I20260812 06:19:59.816233 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:59.832903 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.016s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.833386 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:19:59.844455 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.844985 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:00.096741 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.252s	user 0.146s	sys 0.100s Metrics: {"cfile_cache_miss":725,"cfile_cache_miss_bytes":32610537,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":410,"lbm_read_time_us":16146,"lbm_reads_lt_1ms":765,"lbm_write_time_us":43686,"lbm_writes_lt_1ms":734,"mutex_wait_us":45,"peak_mem_usage":86559345,"reinsert_count":0,"spinlock_wait_cycles":8576,"thread_start_us":80,"threads_started":1,"update_count":3455}
I20260812 06:20:00.097360 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=18.063937
I20260812 06:20:00.158720 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.061s	user 0.030s	sys 0.028s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":27402,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:00.159329 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:00.175753 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.016s	user 0.000s	sys 0.014s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.176512 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:00.344005 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.167s	user 0.128s	sys 0.034s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877107,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":538,"lbm_read_time_us":10098,"lbm_reads_lt_1ms":664,"lbm_write_time_us":36207,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":55936,"update_count":3000}
I20260812 06:20:00.344746 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:20:00.395509 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.051s	user 0.013s	sys 0.032s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21432,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.396149 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:00.407518 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4202,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.408209 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:00.572022 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.164s	user 0.110s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1153,"lbm_read_time_us":11354,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29372,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2500}
I20260812 06:20:00.572767 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=11.118625
I20260812 06:20:00.615129 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.042s	user 0.022s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":18676,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:00.615769 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:00.628520 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4553,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.629158 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:00.786314 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.157s	user 0.098s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":9298,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23839,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:00.787216 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:20:00.856078 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.069s	user 0.041s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24800,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.856650 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:00.870054 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.013s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4288,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.870779 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:01.043648 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.173s	user 0.129s	sys 0.043s 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":824,"lbm_read_time_us":12007,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29915,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:01.044219 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=14.095187
I20260812 06:20:01.104403 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.060s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.104986 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:01.115717 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4030,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.116300 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:01.286878 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.170s	user 0.106s	sys 0.062s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":718,"lbm_read_time_us":11920,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29850,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:20:01.287539 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=11.118625
I20260812 06:20:01.344086 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.056s	user 0.029s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":19281,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.344671 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=6.157687
I20260812 06:20:01.370724 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.026s	user 0.009s	sys 0.014s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8392,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:20:01.371294 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:01.429366 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushMRSOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.058s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1357582,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1531,"drs_written":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2862,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:20:01.430058 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling LogGCOp(abee1a72c0854ad69b098bfed19f29bc): free 128867663 bytes of WAL
I20260812 06:20:01.430286 32171 log_reader.cc:385] T abee1a72c0854ad69b098bfed19f29bc: removed 13 log segments from log reader
I20260812 06:20:01.430328 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000027 (ops 128-132)
I20260812 06:20:01.430357 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000028 (ops 133-136)
I20260812 06:20:01.430430 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000029 (ops 137-141)
I20260812 06:20:01.430464 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000030 (ops 142-146)
I20260812 06:20:01.430553 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000031 (ops 147-150)
I20260812 06:20:01.430595 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000032 (ops 151-155)
I20260812 06:20:01.430613 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000033 (ops 156-160)
I20260812 06:20:01.430649 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000034 (ops 161-164)
I20260812 06:20:01.430687 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000035 (ops 165-169)
I20260812 06:20:01.430723 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000036 (ops 170-174)
I20260812 06:20:01.430763 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000037 (ops 175-179)
I20260812 06:20:01.430799 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000038 (ops 180-184)
I20260812 06:20:01.430840 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000039 (ops 185-189)
I20260812 06:20:01.459406 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: LogGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:20:01.460170 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc): 507 bytes on disk
I20260812 06:20:01.461022 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: UndoDeltaBlockGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":109,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.461789 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=7.149875
I20260812 06:20:01.488485 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.027s	user 0.018s	sys 0.008s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":11568,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:01.488950 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling LogGCOp(abee1a72c0854ad69b098bfed19f29bc): free 12018006 bytes of WAL
I20260812 06:20:01.489157 32171 log_reader.cc:385] T abee1a72c0854ad69b098bfed19f29bc: removed 1 log segments from log reader
I20260812 06:20:01.489217 32171 log.cc:1079] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: Deleting log segment in path: /tmp/dist-test-taskSeGE8u/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515590857419-31844-0/minicluster-data/ts-0-root/wals/abee1a72c0854ad69b098bfed19f29bc/wal-000000040 (ops 190-194)
I20260812 06:20:01.491528 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: LogGCOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:01.491915 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=2.188937
I20260812 06:20:01.503566 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4427,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.504096 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc): perf score=1.000000
I20260812 06:20:01.633159 31844 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.981s	user 1.820s	sys 0.199s
I20260812 06:20:01.741031 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: MajorDeltaCompactionOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.237s	user 0.145s	sys 0.084s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37082160,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":942,"lbm_read_time_us":16867,"lbm_reads_lt_1ms":870,"lbm_write_time_us":39291,"lbm_writes_lt_1ms":843,"mutex_wait_us":30,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":25984,"thread_start_us":90,"threads_started":1,"update_count":4000}
I20260812 06:20:01.741910 32235 maintenance_manager.cc:419] P e82872b8260c4cdc8075848082492b73: Scheduling FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc): perf score=10.126437
I20260812 06:20:01.749559 31844 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.116s	user 0.002s	sys 0.000s
I20260812 06:20:01.750118 31844 tablet_server.cc:179] TabletServer@127.31.25.1:0 shutting down...
I20260812 06:20:01.774993 32171 maintenance_manager.cc:643] P e82872b8260c4cdc8075848082492b73: FlushDeltaMemStoresOp(abee1a72c0854ad69b098bfed19f29bc) complete. Timing: real 0.033s	user 0.009s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14429,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.775667 31844 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:01.776023 31844 tablet_replica.cc:333] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73: stopping tablet replica
I20260812 06:20:01.776163 31844 raft_consensus.cc:2243] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:01.776310 31844 raft_consensus.cc:2272] T abee1a72c0854ad69b098bfed19f29bc P e82872b8260c4cdc8075848082492b73 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:01.780110 31844 tablet_server.cc:196] TabletServer@127.31.25.1:0 shutdown complete.
I20260812 06:20:01.808020 31844 master.cc:562] Master@127.31.25.62:35181 shutting down...
I20260812 06:20:01.812131 31844 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:01.812340 31844 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:01.812422 31844 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0012963fa72145d180094d72dfc147ac: stopping tablet replica
I20260812 06:20:01.824909 31844 master.cc:584] Master@127.31.25.62:35181 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5489 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11042 ms total)

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