[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:17:10.439018 16607 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.55.254:43871
I20260812 06:17:10.440147 16607 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:17:10.440785 16607 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.447764 16613 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.447830 16616 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.447957 16607 server_base.cc:1061] running on GCE node
W20260812 06:17:10.448110 16612 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.448648 16607 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.448743 16607 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:10.448770 16607 hybrid_clock.cc:648] HybridClock initialized: now 1786515430448769 us; error 0 us; skew 500 ppm
I20260812 06:17:10.450727 16607 webserver.cc:533] Webserver started at http://127.16.55.254:33097/ using document root <none> and password file <none>
I20260812 06:17:10.451270 16607 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.451331 16607 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.451527 16607 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.453197 16607 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/master-0-root/instance:
uuid: "4da57338ab574000b0145bd8bb5a5e83"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-tm1g"
I20260812 06:17:10.456784 16607 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:17:10.458922 16621 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.459991 16607 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:10.460140 16607 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/master-0-root
uuid: "4da57338ab574000b0145bd8bb5a5e83"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-tm1g"
I20260812 06:17:10.460253 16607 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.480458 16607 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.481369 16607 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:17:10.481561 16607 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.493083 16607 rpc_server.cc:307] RPC server started. Bound to: 127.16.55.254:43871
I20260812 06:17:10.493106 16679 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.55.254:43871 every 8 connection(s)
I20260812 06:17:10.496349 16680 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.503582 16680 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: Bootstrap starting.
I20260812 06:17:10.506853 16680 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.508335 16680 log.cc:826] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:10.510747 16680 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: No bootstrap required, opened a new log
I20260812 06:17:10.515975 16680 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER }
I20260812 06:17:10.516242 16680 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.516348 16680 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4da57338ab574000b0145bd8bb5a5e83, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.517225 16680 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [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: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER }
I20260812 06:17:10.517446 16680 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.517534 16680 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.517702 16680 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.519109 16680 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER }
I20260812 06:17:10.519747 16680 leader_election.cc:304] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [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: 4da57338ab574000b0145bd8bb5a5e83; no voters: 
I20260812 06:17:10.520200 16680 leader_election.cc:290] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.520321 16683 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.520604 16683 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 1 LEADER]: Becoming Leader. State: Replica: 4da57338ab574000b0145bd8bb5a5e83, State: Running, Role: LEADER
I20260812 06:17:10.521093 16683 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [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: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER }
I20260812 06:17:10.521510 16680 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:10.522987 16685 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4da57338ab574000b0145bd8bb5a5e83. Latest consensus state: current_term: 1 leader_uuid: "4da57338ab574000b0145bd8bb5a5e83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER } }
I20260812 06:17:10.523109 16685 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.523464 16694 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:10.523473 16684 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4da57338ab574000b0145bd8bb5a5e83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4da57338ab574000b0145bd8bb5a5e83" member_type: VOTER } }
I20260812 06:17:10.523679 16684 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:10.526185 16694 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:10.526472 16607 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:10.531890 16694 catalog_manager.cc:1383] Generated new cluster ID: 33d2f3a7369e4c97b24a2bb67b3017f7
I20260812 06:17:10.531965 16694 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:10.550972 16694 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:10.551919 16694 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:10.565303 16694 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: Generated new TSK 0
I20260812 06:17:10.566049 16694 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:10.591591 16607 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:10.594750 16705 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.594789 16706 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:10.594821 16708 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:10.595100 16607 server_base.cc:1061] running on GCE node
I20260812 06:17:10.595382 16607 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:10.595494 16607 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:10.595531 16607 hybrid_clock.cc:648] HybridClock initialized: now 1786515430595531 us; error 0 us; skew 500 ppm
I20260812 06:17:10.596619 16607 webserver.cc:533] Webserver started at http://127.16.55.193:35719/ using document root <none> and password file <none>
I20260812 06:17:10.596809 16607 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:10.596868 16607 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:10.596971 16607 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:10.597385 16607 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/instance:
uuid: "9c1f28105bcb45f7a289c7b6a06e6f04"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-tm1g"
I20260812 06:17:10.599046 16607 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:10.600049 16713 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.600292 16607 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:10.600364 16607 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root
uuid: "9c1f28105bcb45f7a289c7b6a06e6f04"
format_stamp: "Formatted at 2026-08-12 06:17:10 on dist-test-slave-tm1g"
I20260812 06:17:10.600458 16607 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:10.624612 16607 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:10.625079 16607 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:10.625628 16607 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:10.626597 16607 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:10.626652 16607 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.626721 16607 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:10.626762 16607 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:10.633507 16607 rpc_server.cc:307] RPC server started. Bound to: 127.16.55.193:36815
I20260812 06:17:10.633551 16788 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.55.193:36815 every 8 connection(s)
I20260812 06:17:10.644085 16789 heartbeater.cc:344] Connected to a master server at 127.16.55.254:43871
I20260812 06:17:10.644385 16789 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:10.644873 16789 heartbeater.cc:507] Master 127.16.55.254:43871 requested a full tablet report, sending...
I20260812 06:17:10.646466 16633 ts_manager.cc:194] Registered new tserver with Master: 9c1f28105bcb45f7a289c7b6a06e6f04 (127.16.55.193:36815)
I20260812 06:17:10.646615 16607 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012396323s
I20260812 06:17:10.648149 16633 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45756
I20260812 06:17:10.657717 16633 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45770:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:10.673053 16748 tablet_service.cc:1511] Processing CreateTablet for tablet 4b1dfb8545934ceb906fefabc5750639 (DEFAULT_TABLE table=heavy-update-compaction-test [id=ded533739c5744e69bac0f08e8509032]), partition=
I20260812 06:17:10.673583 16748 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4b1dfb8545934ceb906fefabc5750639. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:10.676945 16804 tablet_bootstrap.cc:492] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Bootstrap starting.
I20260812 06:17:10.677874 16804 tablet_bootstrap.cc:654] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:10.679134 16804 tablet_bootstrap.cc:492] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: No bootstrap required, opened a new log
I20260812 06:17:10.679394 16804 ts_tablet_manager.cc:1403] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:10.680012 16804 raft_consensus.cc:359] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c1f28105bcb45f7a289c7b6a06e6f04" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 36815 } }
I20260812 06:17:10.680114 16804 raft_consensus.cc:385] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:10.680138 16804 raft_consensus.cc:740] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9c1f28105bcb45f7a289c7b6a06e6f04, State: Initialized, Role: FOLLOWER
I20260812 06:17:10.680311 16804 consensus_queue.cc:260] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [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: "9c1f28105bcb45f7a289c7b6a06e6f04" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 36815 } }
I20260812 06:17:10.680413 16804 raft_consensus.cc:399] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:10.680464 16804 raft_consensus.cc:493] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:10.680532 16804 raft_consensus.cc:3060] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:10.681288 16804 raft_consensus.cc:515] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c1f28105bcb45f7a289c7b6a06e6f04" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 36815 } }
I20260812 06:17:10.681427 16804 leader_election.cc:304] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [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: 9c1f28105bcb45f7a289c7b6a06e6f04; no voters: 
I20260812 06:17:10.681699 16804 leader_election.cc:290] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:10.681797 16806 raft_consensus.cc:2804] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:10.681979 16806 raft_consensus.cc:697] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 1 LEADER]: Becoming Leader. State: Replica: 9c1f28105bcb45f7a289c7b6a06e6f04, State: Running, Role: LEADER
I20260812 06:17:10.682075 16804 ts_tablet_manager.cc:1434] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:17:10.682219 16806 consensus_queue.cc:237] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [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: "9c1f28105bcb45f7a289c7b6a06e6f04" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 36815 } }
I20260812 06:17:10.682451 16789 heartbeater.cc:499] Master 127.16.55.254:43871 was elected leader, sending a full tablet report...
I20260812 06:17:10.685248 16633 catalog_manager.cc:5719] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 reported cstate change: term changed from 0 to 1, leader changed from <none> to 9c1f28105bcb45f7a289c7b6a06e6f04 (127.16.55.193). New cstate: current_term: 1 leader_uuid: "9c1f28105bcb45f7a289c7b6a06e6f04" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9c1f28105bcb45f7a289c7b6a06e6f04" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 36815 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:10.746665 16607 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.011s	sys 0.013s
I20260812 06:17:10.884689 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushMRSOp(4b1dfb8545934ceb906fefabc5750639): perf score=19.054940
I20260812 06:17:11.079810 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushMRSOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.195s	user 0.136s	sys 0.056s Metrics: {"bytes_written":12717736,"cfile_init":1,"compiler_manager_pool.queue_time_us":257,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1054,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":47650,"lbm_writes_lt_1ms":767,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":168,"threads_started":1,"update_count":1550}
I20260812 06:17:11.081408 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 20743880 bytes of WAL
I20260812 06:17:11.081845 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 2 log segments from log reader
I20260812 06:17:11.081980 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000001 (ops 1-6)
I20260812 06:17:11.082095 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000002 (ops 7-11)
I20260812 06:17:11.088215 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:17:11.088630 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639): 16411396 bytes on disk
I20260812 06:17:11.089233 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:11.089685 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.117429 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.028s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.117959 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.130194 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4871,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.130954 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:11.301635 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.170s	user 0.129s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1271,"lbm_read_time_us":13059,"lbm_reads_lt_1ms":569,"lbm_write_time_us":28583,"lbm_writes_lt_1ms":543,"mutex_wait_us":393,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":353,"threads_started":5,"update_count":2500}
I20260812 06:17:11.302124 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:11.347486 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.045s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16117,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.348074 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.363160 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.363673 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:11.492518 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.129s	user 0.099s	sys 0.028s 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":371,"lbm_read_time_us":8619,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27155,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10368,"update_count":2000}
I20260812 06:17:11.495684 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:11.542614 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.047s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15517,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.543076 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.554147 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.554914 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:11.681945 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.127s	user 0.097s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":166,"lbm_read_time_us":9527,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24633,"lbm_writes_lt_1ms":443,"mutex_wait_us":45,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:17:11.682650 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:11.726210 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.043s	user 0.014s	sys 0.021s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":16326,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.726773 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.738227 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.738812 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:11.864498 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.125s	user 0.105s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":654,"lbm_read_time_us":8916,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23577,"lbm_writes_lt_1ms":443,"mutex_wait_us":347,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":42624,"update_count":2000}
I20260812 06:17:11.865623 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:11.911638 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.046s	user 0.038s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15948,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:11.912297 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:11.923794 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4445,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.924331 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:12.074568 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.150s	user 0.106s	sys 0.043s 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":348,"lbm_read_time_us":11356,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26702,"lbm_writes_lt_1ms":443,"mutex_wait_us":87,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.077559 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:12.118181 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15153,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.118759 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.130466 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.131121 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:12.254546 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.123s	user 0.106s	sys 0.016s 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":1118,"lbm_read_time_us":8433,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24479,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:17:12.255153 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:12.300365 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.045s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15809,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.300992 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.313023 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.313694 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushMRSOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:12.342628 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushMRSOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.029s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1605,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1629,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:12.343417 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 115943166 bytes of WAL
I20260812 06:17:12.343648 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 11 log segments from log reader
I20260812 06:17:12.343693 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000003 (ops 12-16)
I20260812 06:17:12.343742 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000004 (ops 17-21)
I20260812 06:17:12.343784 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000005 (ops 22-26)
I20260812 06:17:12.343840 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000006 (ops 27-31)
I20260812 06:17:12.343879 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000007 (ops 32-36)
I20260812 06:17:12.343930 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000008 (ops 37-41)
I20260812 06:17:12.343967 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000009 (ops 42-46)
I20260812 06:17:12.344007 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000010 (ops 47-51)
I20260812 06:17:12.344044 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000011 (ops 52-56)
I20260812 06:17:12.344082 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000012 (ops 57-61)
I20260812 06:17:12.344120 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000013 (ops 62-66)
I20260812 06:17:12.372273 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:12.372788 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=3.181125
I20260812 06:17:12.391040 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.018s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7434,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:12.391523 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.401484 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3669,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:12.401954 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:12.586701 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.185s	user 0.131s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877329,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1314,"lbm_read_time_us":13593,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36249,"lbm_writes_lt_1ms":643,"mutex_wait_us":259,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:17:12.587477 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:12.639921 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.052s	user 0.019s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21943,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:12.640537 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639): 462 bytes on disk
I20260812 06:17:12.641090 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.641642 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.652889 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4428,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.653375 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:12.805683 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.152s	user 0.104s	sys 0.048s 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":503,"lbm_read_time_us":11818,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30493,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:17:12.806999 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:12.844228 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.037s	user 0.019s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14748,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:12.844766 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.870606 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.025s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.871064 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:12.881291 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3916,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:12.881750 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:13.046527 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.165s	user 0.120s	sys 0.044s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774809,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1809,"lbm_read_time_us":11404,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29044,"lbm_writes_lt_1ms":543,"mutex_wait_us":915,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":36992,"update_count":2500}
I20260812 06:17:13.047245 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:13.106477 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.059s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22032,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.107065 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.118209 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.118848 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:13.284646 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.166s	user 0.109s	sys 0.056s 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":577,"lbm_read_time_us":12579,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28642,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":62208,"update_count":2500}
I20260812 06:17:13.285267 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:13.340616 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.055s	user 0.023s	sys 0.030s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20398,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.341305 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.353574 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.354117 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:13.541817 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.187s	user 0.114s	sys 0.068s 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":297,"lbm_read_time_us":13882,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31298,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2500}
I20260812 06:17:13.542565 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:13.604635 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.062s	user 0.028s	sys 0.032s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22657,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:13.605476 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.623296 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.624137 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:13.799912 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.176s	user 0.099s	sys 0.072s 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":350,"lbm_read_time_us":13654,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30068,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2500}
I20260812 06:17:13.800549 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=11.118625
I20260812 06:17:13.840106 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.039s	user 0.027s	sys 0.009s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16057,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:13.840618 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.853971 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3778,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.854725 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushMRSOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:13.901376 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushMRSOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.046s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":276,"dirs.run_wall_time_us":1452,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1764,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:17:13.902438 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=3.181125
I20260812 06:17:13.923213 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.021s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7349,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:13.923739 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 129773563 bytes of WAL
I20260812 06:17:13.923962 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 13 log segments from log reader
I20260812 06:17:13.924021 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000014 (ops 67-71)
I20260812 06:17:13.924074 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000015 (ops 72-76)
I20260812 06:17:13.924111 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000016 (ops 77-81)
I20260812 06:17:13.924142 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000017 (ops 82-86)
I20260812 06:17:13.924173 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000018 (ops 87-91)
I20260812 06:17:13.924201 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000019 (ops 92-96)
I20260812 06:17:13.924235 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000020 (ops 97-101)
I20260812 06:17:13.924273 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000021 (ops 102-106)
I20260812 06:17:13.924309 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000022 (ops 107-110)
I20260812 06:17:13.924348 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000023 (ops 111-115)
I20260812 06:17:13.924386 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000024 (ops 116-120)
I20260812 06:17:13.924422 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000025 (ops 121-125)
I20260812 06:17:13.924471 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000026 (ops 126-130)
I20260812 06:17:13.954018 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.030s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:17:13.954562 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639): 493 bytes on disk
I20260812 06:17:13.955188 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":102,"lbm_reads_lt_1ms":4}
I20260812 06:17:13.955853 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.971473 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.015s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:13.971992 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 11564893 bytes of WAL
I20260812 06:17:13.972218 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 1 log segments from log reader
I20260812 06:17:13.972263 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000027 (ops 131-134)
I20260812 06:17:13.974673 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:13.974994 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:13.985909 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3600,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:13.986610 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:14.217509 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.231s	user 0.154s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979853,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":591,"lbm_read_time_us":16461,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40897,"lbm_writes_lt_1ms":743,"mutex_wait_us":25,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":14208,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:17:14.218190 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:14.272149 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.054s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23387,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.272810 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.300697 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.028s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6462,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.301249 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.311780 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3980,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.312386 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:14.519397 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.207s	user 0.135s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":524,"lbm_read_time_us":14267,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36183,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:14.520149 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:14.569728 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.049s	user 0.033s	sys 0.012s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":21751,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.570391 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.596206 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.026s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.596660 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.607302 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4060,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.607800 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:14.816322 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.208s	user 0.135s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1036,"lbm_read_time_us":14718,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35823,"lbm_writes_lt_1ms":643,"mutex_wait_us":285,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":3000}
I20260812 06:17:14.817272 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:14.865604 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.048s	user 0.041s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21194,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:14.866201 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.893060 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.027s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5421,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.893558 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:14.904241 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4121,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:14.904740 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:15.100461 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.196s	user 0.147s	sys 0.048s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":552,"lbm_read_time_us":14258,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32046,"lbm_writes_lt_1ms":643,"mutex_wait_us":300,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":3000}
I20260812 06:17:15.101238 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:15.155671 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.054s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23850,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:17:15.156404 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:15.176448 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.020s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.176944 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:15.352820 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.176s	user 0.103s	sys 0.072s 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":403,"lbm_read_time_us":11614,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29043,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:17:15.353525 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=14.095187
I20260812 06:17:15.410745 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.057s	user 0.038s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26894,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:17:15.411369 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:15.427686 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:15.428452 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushMRSOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:15.457440 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushMRSOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.029s	user 0.024s	sys 0.003s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":250,"dirs.run_wall_time_us":1468,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2006,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":7552}
I20260812 06:17:15.458159 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 117302827 bytes of WAL
I20260812 06:17:15.458441 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 12 log segments from log reader
I20260812 06:17:15.458498 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000028 (ops 135-139)
I20260812 06:17:15.458530 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000029 (ops 140-144)
I20260812 06:17:15.458575 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000030 (ops 145-148)
I20260812 06:17:15.458624 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000031 (ops 149-153)
I20260812 06:17:15.458667 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000032 (ops 154-158)
I20260812 06:17:15.458714 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000033 (ops 159-163)
I20260812 06:17:15.458765 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000034 (ops 164-168)
I20260812 06:17:15.458804 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000035 (ops 169-172)
I20260812 06:17:15.458861 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000036 (ops 173-177)
I20260812 06:17:15.458900 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000037 (ops 178-182)
I20260812 06:17:15.458938 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000038 (ops 183-187)
I20260812 06:17:15.458983 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000039 (ops 188-192)
I20260812 06:17:15.486675 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:17:15.487208 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=3.181125
I20260812 06:17:15.499734 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.012s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4547,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:15.500186 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639): 482 bytes on disk
I20260812 06:17:15.500568 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: UndoDeltaBlockGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:17:15.501138 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=2.188937
I20260812 06:17:15.511067 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3691,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:15.511512 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling LogGCOp(4b1dfb8545934ceb906fefabc5750639): free 11564893 bytes of WAL
I20260812 06:17:15.511719 16718 log_reader.cc:385] T 4b1dfb8545934ceb906fefabc5750639: removed 1 log segments from log reader
I20260812 06:17:15.511786 16718 log.cc:1079] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/4b1dfb8545934ceb906fefabc5750639/wal-000000040 (ops 193-196)
I20260812 06:17:15.514896 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: LogGCOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.003s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:15.515272 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639): perf score=1.000000
I20260812 06:17:15.635649 16607 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.889s	user 1.854s	sys 0.111s
I20260812 06:17:15.730532 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: MajorDeltaCompactionOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.215s	user 0.131s	sys 0.084s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1105,"lbm_read_time_us":16065,"lbm_reads_lt_1ms":770,"lbm_write_time_us":37431,"lbm_writes_lt_1ms":743,"mutex_wait_us":55,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":19200,"thread_start_us":109,"threads_started":1,"update_count":3500}
I20260812 06:17:15.731284 16790 maintenance_manager.cc:419] P 9c1f28105bcb45f7a289c7b6a06e6f04: Scheduling FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639): perf score=10.126437
I20260812 06:17:15.744268 16607 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.004s	sys 0.000s
I20260812 06:17:15.745167 16607 tablet_server.cc:179] TabletServer@127.16.55.193:0 shutting down...
I20260812 06:17:15.771448 16718 maintenance_manager.cc:643] P 9c1f28105bcb45f7a289c7b6a06e6f04: FlushDeltaMemStoresOp(4b1dfb8545934ceb906fefabc5750639) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17756,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:15.772230 16607 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:15.772770 16607 tablet_replica.cc:333] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04: stopping tablet replica
I20260812 06:17:15.773033 16607 raft_consensus.cc:2243] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.773274 16607 raft_consensus.cc:2272] T 4b1dfb8545934ceb906fefabc5750639 P 9c1f28105bcb45f7a289c7b6a06e6f04 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.788969 16607 tablet_server.cc:196] TabletServer@127.16.55.193:0 shutdown complete.
I20260812 06:17:15.795090 16607 master.cc:562] Master@127.16.55.254:43871 shutting down...
I20260812 06:17:15.799103 16607 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:15.799319 16607 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:15.799434 16607 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4da57338ab574000b0145bd8bb5a5e83: stopping tablet replica
I20260812 06:17:15.812197 16607 master.cc:584] Master@127.16.55.254:43871 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5464 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:15.903319 16607 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.55.254:43081
I20260812 06:17:15.903739 16607 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.906085 16828 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:15.906142 16825 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.906165 16607 server_base.cc:1061] running on GCE node
W20260812 06:17:15.906085 16824 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.906661 16607 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.906759 16607 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:15.906785 16607 hybrid_clock.cc:648] HybridClock initialized: now 1786515435906785 us; error 0 us; skew 500 ppm
I20260812 06:17:15.907680 16607 webserver.cc:533] Webserver started at http://127.16.55.254:44211/ using document root <none> and password file <none>
I20260812 06:17:15.907825 16607 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.907867 16607 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.907923 16607 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.908290 16607 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/master-0-root/instance:
uuid: "7602fc88dda54a198f78cce84afe3469"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-tm1g"
I20260812 06:17:15.909832 16607 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:15.910894 16833 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.911163 16607 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:17:15.911231 16607 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/master-0-root
uuid: "7602fc88dda54a198f78cce84afe3469"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-tm1g"
I20260812 06:17:15.911330 16607 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:15.926519 16607 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:15.927006 16607 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:15.931563 16607 rpc_server.cc:307] RPC server started. Bound to: 127.16.55.254:43081
I20260812 06:17:15.934110 16891 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.55.254:43081 every 8 connection(s)
I20260812 06:17:15.945154 16892 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:15.947181 16892 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469: Bootstrap starting.
I20260812 06:17:15.948078 16892 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:15.949297 16892 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469: No bootstrap required, opened a new log
I20260812 06:17:15.949735 16892 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER }
I20260812 06:17:15.949826 16892 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:15.949848 16892 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7602fc88dda54a198f78cce84afe3469, State: Initialized, Role: FOLLOWER
I20260812 06:17:15.950083 16892 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [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: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER }
I20260812 06:17:15.950173 16892 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:15.950240 16892 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:15.950286 16892 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:15.951031 16892 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER }
I20260812 06:17:15.951149 16892 leader_election.cc:304] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [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: 7602fc88dda54a198f78cce84afe3469; no voters: 
I20260812 06:17:15.951387 16892 leader_election.cc:290] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:15.951617 16895 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:15.951858 16895 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 1 LEADER]: Becoming Leader. State: Replica: 7602fc88dda54a198f78cce84afe3469, State: Running, Role: LEADER
I20260812 06:17:15.951983 16892 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:15.952030 16895 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [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: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER }
I20260812 06:17:15.952483 16896 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7602fc88dda54a198f78cce84afe3469" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER } }
I20260812 06:17:15.952591 16896 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.952500 16897 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7602fc88dda54a198f78cce84afe3469. Latest consensus state: current_term: 1 leader_uuid: "7602fc88dda54a198f78cce84afe3469" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7602fc88dda54a198f78cce84afe3469" member_type: VOTER } }
I20260812 06:17:15.952795 16897 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:15.953243 16900 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:15.953914 16900 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:15.954111 16607 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:15.955892 16900 catalog_manager.cc:1383] Generated new cluster ID: fc4462e29d034c3291aff5b25b67167b
I20260812 06:17:15.955987 16900 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:15.968007 16900 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:15.968583 16900 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:15.973656 16900 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469: Generated new TSK 0
I20260812 06:17:15.973877 16900 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:15.986928 16607 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:15.989212 16914 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:17:15.989245 16916 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.989411 16607 server_base.cc:1061] running on GCE node
W20260812 06:17:15.989508 16913 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:17:15.989711 16607 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:15.989761 16607 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:17:15.989778 16607 hybrid_clock.cc:648] HybridClock initialized: now 1786515435989778 us; error 0 us; skew 500 ppm
I20260812 06:17:15.990731 16607 webserver.cc:533] Webserver started at http://127.16.55.193:41523/ using document root <none> and password file <none>
I20260812 06:17:15.990916 16607 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:15.990976 16607 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:15.991071 16607 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:15.991498 16607 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/instance:
uuid: "4790b9bafb8846aba2c8695afe28ef22"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-tm1g"
I20260812 06:17:15.993139 16607 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:15.994244 16921 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:15.994632 16607 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:17:15.994728 16607 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root
uuid: "4790b9bafb8846aba2c8695afe28ef22"
format_stamp: "Formatted at 2026-08-12 06:17:15 on dist-test-slave-tm1g"
I20260812 06:17:15.994822 16607 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:17:16.020298 16607 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:16.020750 16607 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:16.021113 16607 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:16.021626 16607 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:16.021689 16607 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.021749 16607 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:16.021799 16607 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:16.026247 16607 rpc_server.cc:307] RPC server started. Bound to: 127.16.55.193:45581
I20260812 06:17:16.026355 16994 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.55.193:45581 every 8 connection(s)
I20260812 06:17:16.036979 16995 heartbeater.cc:344] Connected to a master server at 127.16.55.254:43081
I20260812 06:17:16.037161 16995 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:16.037463 16995 heartbeater.cc:507] Master 127.16.55.254:43081 requested a full tablet report, sending...
I20260812 06:17:16.038391 16846 ts_manager.cc:194] Registered new tserver with Master: 4790b9bafb8846aba2c8695afe28ef22 (127.16.55.193:45581)
I20260812 06:17:16.039095 16607 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012347062s
I20260812 06:17:16.039191 16846 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:53078
I20260812 06:17:16.046959 16846 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:53082:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:17:16.057133 16952 tablet_service.cc:1511] Processing CreateTablet for tablet ec89e652b4f746b2a23cf5532a89f0cb (DEFAULT_TABLE table=heavy-update-compaction-test [id=feb35111ae1347d1a18ad9dccff6352f]), partition=
I20260812 06:17:16.057452 16952 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet ec89e652b4f746b2a23cf5532a89f0cb. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:16.059742 17009 tablet_bootstrap.cc:492] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Bootstrap starting.
I20260812 06:17:16.060609 17009 tablet_bootstrap.cc:654] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:16.061810 17009 tablet_bootstrap.cc:492] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: No bootstrap required, opened a new log
I20260812 06:17:16.061968 17009 ts_tablet_manager.cc:1403] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:16.062520 17009 raft_consensus.cc:359] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4790b9bafb8846aba2c8695afe28ef22" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 45581 } }
I20260812 06:17:16.062613 17009 raft_consensus.cc:385] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:16.062635 17009 raft_consensus.cc:740] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4790b9bafb8846aba2c8695afe28ef22, State: Initialized, Role: FOLLOWER
I20260812 06:17:16.062734 17009 consensus_queue.cc:260] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [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: "4790b9bafb8846aba2c8695afe28ef22" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 45581 } }
I20260812 06:17:16.062796 17009 raft_consensus.cc:399] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:16.062819 17009 raft_consensus.cc:493] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:16.062849 17009 raft_consensus.cc:3060] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:16.063560 17009 raft_consensus.cc:515] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4790b9bafb8846aba2c8695afe28ef22" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 45581 } }
I20260812 06:17:16.063683 17009 leader_election.cc:304] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [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: 4790b9bafb8846aba2c8695afe28ef22; no voters: 
I20260812 06:17:16.063850 17009 leader_election.cc:290] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:16.064066 17011 raft_consensus.cc:2804] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:16.064201 16995 heartbeater.cc:499] Master 127.16.55.254:43081 was elected leader, sending a full tablet report...
I20260812 06:17:16.064173 17009 ts_tablet_manager.cc:1434] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:16.064188 17011 raft_consensus.cc:697] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 1 LEADER]: Becoming Leader. State: Replica: 4790b9bafb8846aba2c8695afe28ef22, State: Running, Role: LEADER
I20260812 06:17:16.064462 17011 consensus_queue.cc:237] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [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: "4790b9bafb8846aba2c8695afe28ef22" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 45581 } }
I20260812 06:17:16.066015 16846 catalog_manager.cc:5719] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4790b9bafb8846aba2c8695afe28ef22 (127.16.55.193). New cstate: current_term: 1 leader_uuid: "4790b9bafb8846aba2c8695afe28ef22" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4790b9bafb8846aba2c8695afe28ef22" member_type: VOTER last_known_addr { host: "127.16.55.193" port: 45581 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:16.127506 16607 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.014s	sys 0.009s
I20260812 06:17:16.277263 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=19.054940
I20260812 06:17:16.435796 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.158s	user 0.119s	sys 0.035s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":185,"dirs.run_wall_time_us":965,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39763,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:17:16.436427 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb): free 20743831 bytes of WAL
I20260812 06:17:16.436662 16926 log_reader.cc:385] T ec89e652b4f746b2a23cf5532a89f0cb: removed 2 log segments from log reader
I20260812 06:17:16.436704 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000001 (ops 1-6)
I20260812 06:17:16.436735 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000002 (ops 7-11)
I20260812 06:17:16.441102 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:17:16.441457 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb): 16411393 bytes on disk
I20260812 06:17:16.441882 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:17:16.442273 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:16.455741 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4737,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.456382 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:16.605540 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.149s	user 0.117s	sys 0.030s 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":584,"lbm_read_time_us":9398,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27284,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":346,"threads_started":5,"update_count":2000}
I20260812 06:17:16.606074 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=12.110812
I20260812 06:17:16.642014 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.036s	user 0.022s	sys 0.012s Metrics: {"bytes_written":13743340,"delete_count":0,"lbm_write_time_us":15074,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:17:16.643424 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.196750
I20260812 06:17:16.654573 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":3792,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:17:16.654995 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:16.807088 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.152s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672247,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":930,"lbm_read_time_us":9968,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25441,"lbm_writes_lt_1ms":443,"mutex_wait_us":274,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11776,"update_count":2000}
I20260812 06:17:16.807726 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:16.857683 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.050s	user 0.027s	sys 0.017s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20714,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:16.858184 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:16.881405 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.023s	user 0.004s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4269,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:16.881963 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:17.073534 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.191s	user 0.151s	sys 0.040s 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":224,"lbm_read_time_us":14434,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28184,"lbm_writes_lt_1ms":543,"mutex_wait_us":54,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:17.074203 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:17.121071 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.047s	user 0.019s	sys 0.025s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20764,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:17:17.121629 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.143903 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.022s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6354,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.144503 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:17.337903 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.193s	user 0.124s	sys 0.062s 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":195,"lbm_read_time_us":12154,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30125,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2500}
I20260812 06:17:17.338774 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:17.383551 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.045s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20007,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:17.384107 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.402278 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7038,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.402859 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:17.562196 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.159s	user 0.105s	sys 0.051s 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":1217,"lbm_read_time_us":12100,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31245,"lbm_writes_lt_1ms":543,"mutex_wait_us":285,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:17:17.562790 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=11.118625
I20260812 06:17:17.601642 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.039s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17049,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:17.602270 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.617398 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.015s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:17.618010 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:17.753993 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.136s	user 0.120s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":631,"lbm_read_time_us":8758,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27379,"lbm_writes_lt_1ms":443,"mutex_wait_us":374,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:17:17.754913 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=10.126437
I20260812 06:17:17.807250 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.052s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19442,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:17.807816 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.818964 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4156,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.819633 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:17.852896 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":257,"dirs.run_wall_time_us":1511,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1708,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:17.853521 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb): free 128867498 bytes of WAL
I20260812 06:17:17.853761 16926 log_reader.cc:385] T ec89e652b4f746b2a23cf5532a89f0cb: removed 13 log segments from log reader
I20260812 06:17:17.853816 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000003 (ops 12-16)
I20260812 06:17:17.853858 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000004 (ops 17-20)
I20260812 06:17:17.853884 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000005 (ops 21-25)
I20260812 06:17:17.853969 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000006 (ops 26-30)
I20260812 06:17:17.854043 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000007 (ops 31-34)
I20260812 06:17:17.854085 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000008 (ops 35-39)
I20260812 06:17:17.854108 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000009 (ops 40-44)
I20260812 06:17:17.854132 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000010 (ops 45-48)
I20260812 06:17:17.854159 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000011 (ops 49-53)
I20260812 06:17:17.854190 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000012 (ops 54-58)
I20260812 06:17:17.854223 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000013 (ops 59-63)
I20260812 06:17:17.854250 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000014 (ops 64-68)
I20260812 06:17:17.854278 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000015 (ops 69-73)
I20260812 06:17:17.887528 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.034s	user 0.000s	sys 0.033s Metrics: {}
I20260812 06:17:17.887984 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.910743 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.022s	user 0.012s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.911185 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:17.921691 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4085,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:17.922168 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb): 482 bytes on disk
I20260812 06:17:17.922657 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:17:17.923256 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:18.096707 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.173s	user 0.129s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877340,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":530,"lbm_read_time_us":11890,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34121,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:17:18.097508 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:18.152040 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.054s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24355,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.152566 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:18.165262 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4575,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.165817 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:18.321198 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.155s	user 0.108s	sys 0.044s 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":1258,"lbm_read_time_us":11713,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28299,"lbm_writes_lt_1ms":543,"mutex_wait_us":570,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:17:18.321888 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:18.377075 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.055s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24308,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.377630 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:18.534226 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.156s	user 0.118s	sys 0.033s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":534,"lbm_read_time_us":9494,"lbm_reads_lt_1ms":463,"lbm_write_time_us":26238,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2000}
I20260812 06:17:18.534936 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:18.586256 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.051s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":19284,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.586823 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:18.598534 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.012s	user 0.011s	sys 0.000s 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:17:18.599035 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:18.781255 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.182s	user 0.106s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":274,"lbm_read_time_us":12731,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30048,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24832,"update_count":2500}
I20260812 06:17:18.781873 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:18.831856 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.050s	user 0.022s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17533,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:18.832337 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:18.844161 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4593,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:18.844749 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:19.005834 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.161s	user 0.107s	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":775,"lbm_read_time_us":10327,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32521,"lbm_writes_lt_1ms":543,"mutex_wait_us":5,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2500}
I20260812 06:17:19.006403 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=11.118625
I20260812 06:17:19.043792 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.037s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15880,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.044344 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.070477 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.026s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5915,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.070935 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.081686 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4165,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.082181 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:19.231937 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.150s	user 0.119s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":114,"lbm_read_time_us":11223,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30150,"lbm_writes_lt_1ms":543,"mutex_wait_us":46,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:17:19.232636 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=11.118625
I20260812 06:17:19.268266 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":14639,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:19.268952 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.294632 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.025s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5945,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.295202 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.307664 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4365,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.308470 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:19.340975 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":239,"dirs.run_wall_time_us":1674,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2192,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:19.341722 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb): free 124257263 bytes of WAL
I20260812 06:17:19.342017 16926 log_reader.cc:385] T ec89e652b4f746b2a23cf5532a89f0cb: removed 12 log segments from log reader
I20260812 06:17:19.342077 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000016 (ops 74-78)
I20260812 06:17:19.342118 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000017 (ops 79-83)
I20260812 06:17:19.342146 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000018 (ops 84-88)
I20260812 06:17:19.342170 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000019 (ops 89-93)
I20260812 06:17:19.342197 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000020 (ops 94-98)
I20260812 06:17:19.342227 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000021 (ops 99-103)
I20260812 06:17:19.342250 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000022 (ops 104-108)
I20260812 06:17:19.342275 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000023 (ops 109-113)
I20260812 06:17:19.342336 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000024 (ops 114-118)
I20260812 06:17:19.342365 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000025 (ops 119-122)
I20260812 06:17:19.342463 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000026 (ops 123-127)
I20260812 06:17:19.342495 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000027 (ops 128-132)
I20260812 06:17:19.374186 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.032s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:17:19.374924 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb): 483 bytes on disk
I20260812 06:17:19.375463 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:17:19.376019 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=3.181125
I20260812 06:17:19.387998 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.012s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4537,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:19.388435 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.409677 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.021s	user 0.000s	sys 0.017s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3754,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:19.412910 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:19.657711 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.245s	user 0.184s	sys 0.060s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979850,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":762,"lbm_read_time_us":16975,"lbm_reads_lt_1ms":775,"lbm_write_time_us":42875,"lbm_writes_lt_1ms":743,"mutex_wait_us":281,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12544,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:17:19.658427 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=18.063937
I20260812 06:17:19.732877 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.074s	user 0.051s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":33479,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:17:19.733429 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:19.753198 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6744,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:19.753733 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:19.975698 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.222s	user 0.150s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1105,"lbm_read_time_us":15081,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34975,"lbm_writes_lt_1ms":643,"mutex_wait_us":329,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":3000}
I20260812 06:17:19.976513 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=18.063937
I20260812 06:17:20.049906 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.073s	user 0.035s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27803,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2500}
I20260812 06:17:20.050537 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.061570 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":4248,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.062330 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:20.269888 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.207s	user 0.146s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877103,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":308,"lbm_read_time_us":13693,"lbm_reads_lt_1ms":672,"lbm_write_time_us":38079,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":3000}
I20260812 06:17:20.270571 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:20.336421 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.066s	user 0.033s	sys 0.013s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21055,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.336961 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.351152 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.014s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5479,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.351637 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:20.555542 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.204s	user 0.154s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":244,"lbm_read_time_us":13585,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36818,"lbm_writes_lt_1ms":543,"mutex_wait_us":98,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19584,"update_count":2500}
I20260812 06:17:20.556248 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:20.621569 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.065s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24169,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.622222 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.639977 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.017s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.640635 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:20.809451 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.169s	user 0.108s	sys 0.061s 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":436,"lbm_read_time_us":12926,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29319,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:17:20.810213 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=14.095187
I20260812 06:17:20.868654 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.058s	user 0.021s	sys 0.035s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":22177,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:20.869285 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.880149 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.880664 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:20.921005 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushMRSOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.040s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":236,"dirs.run_wall_time_us":1737,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1499,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:20.921916 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb): free 121006640 bytes of WAL
I20260812 06:17:20.922187 16926 log_reader.cc:385] T ec89e652b4f746b2a23cf5532a89f0cb: removed 12 log segments from log reader
I20260812 06:17:20.922261 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000028 (ops 133-137)
I20260812 06:17:20.922339 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000029 (ops 138-142)
I20260812 06:17:20.922394 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000030 (ops 143-147)
I20260812 06:17:20.922437 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000031 (ops 148-152)
I20260812 06:17:20.922475 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000032 (ops 153-156)
I20260812 06:17:20.922515 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000033 (ops 157-161)
I20260812 06:17:20.922555 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000034 (ops 162-166)
I20260812 06:17:20.922595 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000035 (ops 167-171)
I20260812 06:17:20.922636 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000036 (ops 172-176)
I20260812 06:17:20.922675 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000037 (ops 177-181)
I20260812 06:17:20.922715 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000038 (ops 182-186)
I20260812 06:17:20.922755 16926 log.cc:1079] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: Deleting log segment in path: /tmp/dist-test-taskZd1P9n/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515430427771-16607-0/minicluster-data/ts-0-root/wals/ec89e652b4f746b2a23cf5532a89f0cb/wal-000000039 (ops 187-191)
I20260812 06:17:20.950073 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: LogGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.028s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:17:20.950526 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb): 462 bytes on disk
I20260812 06:17:20.951071 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: UndoDeltaBlockGCOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:17:20.951761 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.973574 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.022s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6214,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.974077 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=2.188937
I20260812 06:17:20.984997 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:20.985468 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=1.000000
I20260812 06:17:21.115003 16607 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.987s	user 1.858s	sys 0.175s
I20260812 06:17:21.209772 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: MajorDeltaCompactionOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.224s	user 0.159s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":574,"lbm_read_time_us":14460,"lbm_reads_lt_1ms":770,"lbm_write_time_us":38042,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":101,"threads_started":1,"update_count":3500}
I20260812 06:17:21.210705 16997 maintenance_manager.cc:419] P 4790b9bafb8846aba2c8695afe28ef22: Scheduling FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb): perf score=10.126437
I20260812 06:17:21.217490 16607 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.102s	user 0.001s	sys 0.000s
I20260812 06:17:21.218173 16607 tablet_server.cc:179] TabletServer@127.16.55.193:0 shutting down...
I20260812 06:17:21.243742 16926 maintenance_manager.cc:643] P 4790b9bafb8846aba2c8695afe28ef22: FlushDeltaMemStoresOp(ec89e652b4f746b2a23cf5532a89f0cb) complete. Timing: real 0.033s	user 0.031s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14768,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:21.244755 16607 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:21.244979 16607 tablet_replica.cc:333] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22: stopping tablet replica
I20260812 06:17:21.245188 16607 raft_consensus.cc:2243] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.245434 16607 raft_consensus.cc:2272] T ec89e652b4f746b2a23cf5532a89f0cb P 4790b9bafb8846aba2c8695afe28ef22 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.249013 16607 tablet_server.cc:196] TabletServer@127.16.55.193:0 shutdown complete.
I20260812 06:17:21.267992 16607 master.cc:562] Master@127.16.55.254:43081 shutting down...
I20260812 06:17:21.271502 16607 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:21.271677 16607 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:21.271728 16607 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7602fc88dda54a198f78cce84afe3469: stopping tablet replica
I20260812 06:17:21.283926 16607 master.cc:584] Master@127.16.55.254:43081 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5472 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10938 ms total)

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