[==========] 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:18:36.198949 25700 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.25.62:44933
I20260812 06:18:36.200057 25700 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:18:36.200700 25700 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.209725 25709 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:18:36.209838 25700 server_base.cc:1061] running on GCE node
W20260812 06:18:36.209729 25706 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.210214 25707 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.210893 25700 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.211053 25700 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.211112 25700 hybrid_clock.cc:648] HybridClock initialized: now 1786515516211109 us; error 0 us; skew 500 ppm
I20260812 06:18:36.213722 25700 webserver.cc:533] Webserver started at http://127.25.25.62:40403/ using document root <none> and password file <none>
I20260812 06:18:36.214406 25700 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.214480 25700 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.214723 25700 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.216604 25700 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/master-0-root/instance:
uuid: "1af7219349c8423daccc26986833102b"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-t7g5"
I20260812 06:18:36.220641 25700 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.002s	sys 0.004s
I20260812 06:18:36.223872 25715 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.225345 25700 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:36.225564 25700 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/master-0-root
uuid: "1af7219349c8423daccc26986833102b"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-t7g5"
I20260812 06:18:36.225776 25700 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.256681 25700 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.257409 25700 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:18:36.257570 25700 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.265498 25700 rpc_server.cc:307] RPC server started. Bound to: 127.25.25.62:44933
I20260812 06:18:36.265522 25808 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.25.62:44933 every 8 connection(s)
I20260812 06:18:36.268028 25809 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.273965 25809 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: Bootstrap starting.
I20260812 06:18:36.276577 25809 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.277725 25809 log.cc:826] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:36.279803 25809 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: No bootstrap required, opened a new log
I20260812 06:18:36.282984 25809 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1af7219349c8423daccc26986833102b" member_type: VOTER }
I20260812 06:18:36.283195 25809 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.283247 25809 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1af7219349c8423daccc26986833102b, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.283900 25809 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [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: "1af7219349c8423daccc26986833102b" member_type: VOTER }
I20260812 06:18:36.284056 25809 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.284112 25809 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.284246 25809 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.285131 25809 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1af7219349c8423daccc26986833102b" member_type: VOTER }
I20260812 06:18:36.285616 25809 leader_election.cc:304] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [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: 1af7219349c8423daccc26986833102b; no voters: 
I20260812 06:18:36.285989 25809 leader_election.cc:290] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.286166 25813 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.286408 25813 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 1 LEADER]: Becoming Leader. State: Replica: 1af7219349c8423daccc26986833102b, State: Running, Role: LEADER
I20260812 06:18:36.286839 25813 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [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: "1af7219349c8423daccc26986833102b" member_type: VOTER }
I20260812 06:18:36.287596 25809 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:36.289520 25814 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1af7219349c8423daccc26986833102b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1af7219349c8423daccc26986833102b" member_type: VOTER } }
I20260812 06:18:36.289784 25814 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.289716 25815 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1af7219349c8423daccc26986833102b. Latest consensus state: current_term: 1 leader_uuid: "1af7219349c8423daccc26986833102b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1af7219349c8423daccc26986833102b" member_type: VOTER } }
I20260812 06:18:36.289852 25815 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:36.290426 25826 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:36.290894 25700 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:36.293737 25826 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:36.299050 25826 catalog_manager.cc:1383] Generated new cluster ID: ad500ec685b6483d99b20a6a2f0292ae
I20260812 06:18:36.299149 25826 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:36.315927 25826 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:36.316910 25826 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:36.331775 25826 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: Generated new TSK 0
I20260812 06:18:36.332970 25826 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:36.356771 25700 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:36.360042 25841 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:36.360219 25844 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:18:36.360208 25700 server_base.cc:1061] running on GCE node
W20260812 06:18:36.360211 25842 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:36.360603 25700 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:36.360649 25700 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:36.360663 25700 hybrid_clock.cc:648] HybridClock initialized: now 1786515516360664 us; error 0 us; skew 500 ppm
I20260812 06:18:36.361580 25700 webserver.cc:533] Webserver started at http://127.25.25.1:39203/ using document root <none> and password file <none>
I20260812 06:18:36.361783 25700 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:36.361838 25700 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:36.361918 25700 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:36.362314 25700 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/instance:
uuid: "70765be6e79146cb86cdbb4719af20d2"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-t7g5"
I20260812 06:18:36.364367 25700 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:36.365790 25849 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.366101 25700 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:36.366205 25700 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root
uuid: "70765be6e79146cb86cdbb4719af20d2"
format_stamp: "Formatted at 2026-08-12 06:18:36 on dist-test-slave-t7g5"
I20260812 06:18:36.366293 25700 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:36.373782 25700 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:36.374277 25700 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:36.374781 25700 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:36.375705 25700 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:36.375761 25700 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.375823 25700 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:36.375851 25700 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:36.382972 25700 rpc_server.cc:307] RPC server started. Bound to: 127.25.25.1:43945
I20260812 06:18:36.383249 25945 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.25.1:43945 every 8 connection(s)
I20260812 06:18:36.395498 25948 heartbeater.cc:344] Connected to a master server at 127.25.25.62:44933
I20260812 06:18:36.395797 25948 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:36.396358 25948 heartbeater.cc:507] Master 127.25.25.62:44933 requested a full tablet report, sending...
I20260812 06:18:36.398061 25747 ts_manager.cc:194] Registered new tserver with Master: 70765be6e79146cb86cdbb4719af20d2 (127.25.25.1:43945)
I20260812 06:18:36.398824 25700 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014827993s
I20260812 06:18:36.399641 25747 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45510
I20260812 06:18:36.410620 25747 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45524:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:36.427484 25895 tablet_service.cc:1511] Processing CreateTablet for tablet 78016b135fcb4523a682c06f24a7dfe1 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7705ba6eebab46be94e0221e9aa96319]), partition=
I20260812 06:18:36.427975 25895 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 78016b135fcb4523a682c06f24a7dfe1. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:36.430358 25964 tablet_bootstrap.cc:492] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Bootstrap starting.
I20260812 06:18:36.431921 25964 tablet_bootstrap.cc:654] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:36.433277 25964 tablet_bootstrap.cc:492] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: No bootstrap required, opened a new log
I20260812 06:18:36.433403 25964 ts_tablet_manager.cc:1403] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:36.433940 25964 raft_consensus.cc:359] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70765be6e79146cb86cdbb4719af20d2" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 43945 } }
I20260812 06:18:36.434074 25964 raft_consensus.cc:385] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:36.434160 25964 raft_consensus.cc:740] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 70765be6e79146cb86cdbb4719af20d2, State: Initialized, Role: FOLLOWER
I20260812 06:18:36.434306 25964 consensus_queue.cc:260] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [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: "70765be6e79146cb86cdbb4719af20d2" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 43945 } }
I20260812 06:18:36.434453 25964 raft_consensus.cc:399] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:36.434530 25964 raft_consensus.cc:493] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:36.434628 25964 raft_consensus.cc:3060] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:36.435675 25964 raft_consensus.cc:515] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70765be6e79146cb86cdbb4719af20d2" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 43945 } }
I20260812 06:18:36.435833 25964 leader_election.cc:304] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [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: 70765be6e79146cb86cdbb4719af20d2; no voters: 
I20260812 06:18:36.436072 25964 leader_election.cc:290] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:36.436275 25967 raft_consensus.cc:2804] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:36.436465 25964 ts_tablet_manager.cc:1434] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:36.436542 25967 raft_consensus.cc:697] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 1 LEADER]: Becoming Leader. State: Replica: 70765be6e79146cb86cdbb4719af20d2, State: Running, Role: LEADER
I20260812 06:18:36.436710 25948 heartbeater.cc:499] Master 127.25.25.62:44933 was elected leader, sending a full tablet report...
I20260812 06:18:36.436740 25967 consensus_queue.cc:237] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [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: "70765be6e79146cb86cdbb4719af20d2" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 43945 } }
I20260812 06:18:36.439692 25747 catalog_manager.cc:5719] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 70765be6e79146cb86cdbb4719af20d2 (127.25.25.1). New cstate: current_term: 1 leader_uuid: "70765be6e79146cb86cdbb4719af20d2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "70765be6e79146cb86cdbb4719af20d2" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 43945 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:36.515856 25700 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.021s	sys 0.009s
I20260812 06:18:36.634577 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1): perf score=15.086190
I20260812 06:18:36.811309 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.176s	user 0.139s	sys 0.036s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":215,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":952,"drs_written":1,"lbm_read_time_us":93,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43510,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":118,"threads_started":1,"update_count":1500}
I20260812 06:18:36.813033 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling LogGCOp(78016b135fcb4523a682c06f24a7dfe1): free 8725963 bytes of WAL
I20260812 06:18:36.813514 25858 log_reader.cc:385] T 78016b135fcb4523a682c06f24a7dfe1: removed 1 log segments from log reader
I20260812 06:18:36.813617 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000001 (ops 1-6)
I20260812 06:18:36.816462 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: LogGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:36.816960 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1): 12308959 bytes on disk
I20260812 06:18:36.817770 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.001s	user 0.001s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.818197 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:36.838136 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.020s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6942,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.838722 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:36.982360 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.143s	user 0.108s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1285,"lbm_read_time_us":11123,"lbm_reads_lt_1ms":460,"lbm_write_time_us":25479,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":33152,"thread_start_us":378,"threads_started":5,"update_count":2000}
I20260812 06:18:36.983186 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.032248 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.049s	user 0.027s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20089,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.032888 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.043744 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.044471 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.167757 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.123s	user 0.110s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1671,"lbm_read_time_us":9725,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23788,"lbm_writes_lt_1ms":443,"mutex_wait_us":479,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:37.168267 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.208825 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.040s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14088,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.209342 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.219911 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3863,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.220386 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.337627 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.117s	user 0.101s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":8593,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23338,"lbm_writes_lt_1ms":443,"mutex_wait_us":49,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:37.338194 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.389248 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.050s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14009,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.389860 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.400887 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.401417 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.553476 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.152s	user 0.087s	sys 0.055s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1131,"lbm_read_time_us":10885,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21890,"lbm_writes_lt_1ms":443,"mutex_wait_us":399,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":2000}
I20260812 06:18:37.554286 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.596720 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.042s	user 0.022s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14719,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.597218 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.608652 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.609104 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.731364 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.122s	user 0.110s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":8701,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23940,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:18:37.731838 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.769070 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.037s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14566,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.769600 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.782924 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.013s	user 0.002s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.783700 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.902010 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.118s	user 0.102s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1009,"lbm_read_time_us":9551,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21499,"lbm_writes_lt_1ms":443,"mutex_wait_us":390,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:18:37.902595 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:37.947059 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.044s	user 0.031s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15645,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.947527 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:37.957818 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3898,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.958443 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:37.990355 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1295,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1840,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:37.991164 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling LogGCOp(78016b135fcb4523a682c06f24a7dfe1): free 124257180 bytes of WAL
I20260812 06:18:37.991374 25858 log_reader.cc:385] T 78016b135fcb4523a682c06f24a7dfe1: removed 12 log segments from log reader
I20260812 06:18:37.991415 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000002 (ops 7-11)
I20260812 06:18:37.991447 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000003 (ops 12-16)
I20260812 06:18:37.991482 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000004 (ops 17-21)
I20260812 06:18:37.991506 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000005 (ops 22-26)
I20260812 06:18:37.991539 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000006 (ops 27-31)
I20260812 06:18:37.991571 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000007 (ops 32-36)
I20260812 06:18:37.991605 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000008 (ops 37-40)
I20260812 06:18:37.991638 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000009 (ops 41-45)
I20260812 06:18:37.991671 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000010 (ops 46-50)
I20260812 06:18:37.991703 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000011 (ops 51-55)
I20260812 06:18:37.991735 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000012 (ops 56-60)
I20260812 06:18:37.991768 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000013 (ops 61-65)
I20260812 06:18:38.017076 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: LogGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:38.017540 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1): 447 bytes on disk
I20260812 06:18:38.018076 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:18:38.018586 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=3.181125
I20260812 06:18:38.035392 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.017s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4635981,"delete_count":0,"lbm_write_time_us":6649,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:18:38.035948 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:38.046183 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3301,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:18:38.046685 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:38.227770 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.181s	user 0.114s	sys 0.054s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836368,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":702,"lbm_read_time_us":13059,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32748,"lbm_writes_lt_1ms":643,"mutex_wait_us":86,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:38.228343 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=14.095187
I20260812 06:18:38.279660 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.051s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.280103 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:38.291814 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4293,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.292471 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:38.462733 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.170s	user 0.119s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":11402,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32103,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:18:38.463357 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=14.095187
I20260812 06:18:38.517814 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.054s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18710,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.518309 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:38.528628 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.529202 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:38.711866 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.182s	user 0.122s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":294,"lbm_read_time_us":12335,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31184,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.712436 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=14.095187
I20260812 06:18:38.755846 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19221,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.756398 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:38.916428 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.160s	user 0.126s	sys 0.032s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":248,"lbm_read_time_us":12149,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24801,"lbm_writes_lt_1ms":443,"mutex_wait_us":118,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:18:38.917011 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=11.118625
I20260812 06:18:38.954176 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.037s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15248,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:38.954643 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:38.966464 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4558,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.967180 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:39.106384 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.139s	user 0.110s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":227,"lbm_read_time_us":7855,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28682,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:39.106968 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=11.118625
I20260812 06:18:39.140832 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.034s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14859,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:39.141357 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:39.156701 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5682,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.157547 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:39.297049 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.139s	user 0.114s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1237,"lbm_read_time_us":9232,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26521,"lbm_writes_lt_1ms":443,"mutex_wait_us":565,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:39.297999 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:39.336162 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.038s	user 0.015s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16590,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:39.336688 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:39.348065 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3870,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.348693 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:39.376415 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.028s	user 0.022s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":46,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1148,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1548,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:39.377246 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling LogGCOp(78016b135fcb4523a682c06f24a7dfe1): free 112692432 bytes of WAL
I20260812 06:18:39.377485 25858 log_reader.cc:385] T 78016b135fcb4523a682c06f24a7dfe1: removed 11 log segments from log reader
I20260812 06:18:39.377534 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000014 (ops 66-70)
I20260812 06:18:39.377570 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000015 (ops 71-75)
I20260812 06:18:39.377609 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000016 (ops 76-80)
I20260812 06:18:39.377676 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000017 (ops 81-85)
I20260812 06:18:39.377725 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000018 (ops 86-90)
I20260812 06:18:39.377761 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000019 (ops 91-95)
I20260812 06:18:39.377801 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000020 (ops 96-100)
I20260812 06:18:39.377841 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000021 (ops 101-105)
I20260812 06:18:39.377882 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000022 (ops 106-110)
I20260812 06:18:39.377919 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000023 (ops 111-115)
I20260812 06:18:39.377959 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000024 (ops 116-120)
I20260812 06:18:39.403164 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: LogGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.026s	user 0.001s	sys 0.023s Metrics: {}
I20260812 06:18:39.403623 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1): 447 bytes on disk
I20260812 06:18:39.404114 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.404685 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=3.181125
I20260812 06:18:39.419521 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4487,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:39.420017 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:39.432377 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4409,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.432978 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:39.606840 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.174s	user 0.133s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836364,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":754,"lbm_read_time_us":11667,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31810,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":95,"threads_started":1,"update_count":3000}
I20260812 06:18:39.607419 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=14.095187
I20260812 06:18:39.659785 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.052s	user 0.038s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19343,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.660385 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:39.671280 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.672014 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:39.828106 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.156s	user 0.123s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":937,"lbm_read_time_us":10530,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31049,"lbm_writes_lt_1ms":543,"mutex_wait_us":303,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18944,"update_count":2500}
I20260812 06:18:39.828624 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=11.118625
I20260812 06:18:39.859863 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.031s	user 0.024s	sys 0.005s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":13813,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:39.860368 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:39.876128 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.016s	user 0.004s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5938,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.876799 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.018774 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.142s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":9412,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24963,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2000}
I20260812 06:18:40.019508 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:40.062717 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.041s	user 0.008s	sys 0.032s Metrics: {"bytes_written":12594659,"delete_count":0,"lbm_write_time_us":13284,"lbm_writes_lt_1ms":310,"reinsert_count":0,"update_count":1535}
I20260812 06:18:40.063371 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:40.074656 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3815484,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":96,"reinsert_count":0,"update_count":465}
I20260812 06:18:40.076508 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.222481 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.146s	user 0.118s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631306,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":158,"lbm_read_time_us":10094,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23375,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2000}
I20260812 06:18:40.223115 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:40.262522 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.039s	user 0.015s	sys 0.016s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13397,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.263037 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:40.278877 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5937,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.279419 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.399858 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.120s	user 0.084s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":124,"lbm_read_time_us":9295,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21999,"lbm_writes_lt_1ms":443,"mutex_wait_us":15,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6656,"update_count":2000}
I20260812 06:18:40.400455 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:40.441267 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.041s	user 0.008s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13466,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.441994 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:40.453138 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3928,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.453871 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.582165 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.127s	user 0.115s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":9510,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23280,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":118016,"update_count":2000}
I20260812 06:18:40.582796 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:40.628839 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.046s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13382,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.629401 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:40.640131 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.640695 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.787866 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.147s	user 0.110s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1306,"lbm_read_time_us":10215,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23047,"lbm_writes_lt_1ms":443,"mutex_wait_us":419,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:18:40.788617 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:40.833914 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.045s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14823,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:40.834545 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:40.847743 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.848265 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:40.877491 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushMRSOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275446,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":354,"dirs.run_wall_time_us":1275,"drs_written":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1977,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:40.878301 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling LogGCOp(78016b135fcb4523a682c06f24a7dfe1): free 132571504 bytes of WAL
I20260812 06:18:40.878553 25858 log_reader.cc:385] T 78016b135fcb4523a682c06f24a7dfe1: removed 13 log segments from log reader
I20260812 06:18:40.878614 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000025 (ops 121-125)
I20260812 06:18:40.878651 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000026 (ops 126-130)
I20260812 06:18:40.878675 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000027 (ops 131-135)
I20260812 06:18:40.878701 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000028 (ops 136-140)
I20260812 06:18:40.878724 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000029 (ops 141-145)
I20260812 06:18:40.878746 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000030 (ops 146-150)
I20260812 06:18:40.878768 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000031 (ops 151-155)
I20260812 06:18:40.878799 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000032 (ops 156-160)
I20260812 06:18:40.878835 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000033 (ops 161-164)
I20260812 06:18:40.878873 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000034 (ops 165-169)
I20260812 06:18:40.878911 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000035 (ops 170-174)
I20260812 06:18:40.878933 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000036 (ops 175-178)
I20260812 06:18:40.878968 25858 log.cc:1079] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/78016b135fcb4523a682c06f24a7dfe1/wal-000000037 (ops 179-183)
I20260812 06:18:40.906590 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: LogGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:40.907163 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1): 483 bytes on disk
I20260812 06:18:40.907608 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: UndoDeltaBlockGCOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.908121 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=4.173312
I20260812 06:18:40.934764 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.026s	user 0.010s	sys 0.015s Metrics: {"bytes_written":5907729,"delete_count":0,"lbm_write_time_us":7471,"lbm_writes_lt_1ms":147,"reinsert_count":0,"update_count":720}
I20260812 06:18:40.935253 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.196750
I20260812 06:18:40.942242 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.007s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2297554,"delete_count":0,"lbm_write_time_us":2139,"lbm_writes_lt_1ms":59,"reinsert_count":0,"update_count":280}
I20260812 06:18:40.942773 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:41.145607 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.203s	user 0.154s	sys 0.044s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836334,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":131,"lbm_read_time_us":13789,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32602,"lbm_writes_lt_1ms":643,"mutex_wait_us":34,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:18:41.146257 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=14.095187
I20260812 06:18:41.210052 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.064s	user 0.036s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20083,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.210755 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=2.188937
I20260812 06:18:41.221886 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.222460 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:41.369084 25700 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.853s	user 1.750s	sys 0.152s
I20260812 06:18:41.386158 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.163s	user 0.111s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11628,"lbm_reads_lt_1ms":568,"lbm_write_time_us":27541,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:41.386664 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1): perf score=10.126437
I20260812 06:18:41.410324 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: FlushDeltaMemStoresOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.023s	user 0.019s	sys 0.004s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":10735,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.410789 25949 maintenance_manager.cc:419] P 70765be6e79146cb86cdbb4719af20d2: Scheduling MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1): perf score=1.000000
I20260812 06:18:41.434134 25700 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.064s	user 0.004s	sys 0.000s
I20260812 06:18:41.434899 25700 tablet_server.cc:179] TabletServer@127.25.25.1:0 shutting down...
I20260812 06:18:41.509289 25858 maintenance_manager.cc:643] P 70765be6e79146cb86cdbb4719af20d2: MajorDeltaCompactionOp(78016b135fcb4523a682c06f24a7dfe1) complete. Timing: real 0.098s	user 0.066s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16528783,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":730,"lbm_read_time_us":5723,"lbm_reads_lt_1ms":367,"lbm_write_time_us":21290,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":342,"mutex_wait_us":105,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.510206 25700 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:41.510625 25700 tablet_replica.cc:333] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2: stopping tablet replica
I20260812 06:18:41.510847 25700 raft_consensus.cc:2243] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:41.511173 25700 raft_consensus.cc:2272] T 78016b135fcb4523a682c06f24a7dfe1 P 70765be6e79146cb86cdbb4719af20d2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:41.526271 25700 tablet_server.cc:196] TabletServer@127.25.25.1:0 shutdown complete.
I20260812 06:18:41.542479 25700 master.cc:562] Master@127.25.25.62:44933 shutting down...
I20260812 06:18:41.546284 25700 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:41.546603 25700 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:41.546756 25700 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1af7219349c8423daccc26986833102b: stopping tablet replica
I20260812 06:18:41.559944 25700 master.cc:584] Master@127.25.25.62:44933 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5443 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:41.641647 25700 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.25.25.62:43467
I20260812 06:18:41.642071 25700 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.644081 25996 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:18:41.644186 25994 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.644119 25998 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:18:41.644122 25700 server_base.cc:1061] running on GCE node
I20260812 06:18:41.644541 25700 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.644582 25700 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.644595 25700 hybrid_clock.cc:648] HybridClock initialized: now 1786515521644595 us; error 0 us; skew 500 ppm
I20260812 06:18:41.645366 25700 webserver.cc:533] Webserver started at http://127.25.25.62:35359/ using document root <none> and password file <none>
I20260812 06:18:41.645524 25700 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.645576 25700 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.645638 25700 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.646034 25700 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/master-0-root/instance:
uuid: "61f55bbae498460a874c2f6f0a2eb8ff"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-t7g5"
I20260812 06:18:41.647740 25700 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:41.648927 26005 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.649199 25700 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:41.649276 25700 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/master-0-root
uuid: "61f55bbae498460a874c2f6f0a2eb8ff"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-t7g5"
I20260812 06:18:41.649353 25700 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:41.656720 25700 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.657136 25700 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.662734 25700 rpc_server.cc:307] RPC server started. Bound to: 127.25.25.62:43467
I20260812 06:18:41.665584 26079 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.25.62:43467 every 8 connection(s)
I20260812 06:18:41.675930 26081 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.677834 26081 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff: Bootstrap starting.
I20260812 06:18:41.678607 26081 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.679960 26081 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff: No bootstrap required, opened a new log
I20260812 06:18:41.680343 26081 raft_consensus.cc:359] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER }
I20260812 06:18:41.680445 26081 raft_consensus.cc:385] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.680474 26081 raft_consensus.cc:740] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 61f55bbae498460a874c2f6f0a2eb8ff, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.680593 26081 consensus_queue.cc:260] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [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: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER }
I20260812 06:18:41.680651 26081 raft_consensus.cc:399] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.680678 26081 raft_consensus.cc:493] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.680711 26081 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.681401 26081 raft_consensus.cc:515] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER }
I20260812 06:18:41.681524 26081 leader_election.cc:304] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [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: 61f55bbae498460a874c2f6f0a2eb8ff; no voters: 
I20260812 06:18:41.681722 26081 leader_election.cc:290] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.681869 26087 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.682072 26087 raft_consensus.cc:697] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 1 LEADER]: Becoming Leader. State: Replica: 61f55bbae498460a874c2f6f0a2eb8ff, State: Running, Role: LEADER
I20260812 06:18:41.682173 26081 sys_catalog.cc:565] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:41.682368 26087 consensus_queue.cc:237] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [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: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER }
I20260812 06:18:41.683038 26091 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [sys.catalog]: SysCatalogTable state changed. Reason: New leader 61f55bbae498460a874c2f6f0a2eb8ff. Latest consensus state: current_term: 1 leader_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER } }
I20260812 06:18:41.683149 26091 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.683441 26103 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:41.683895 26090 sys_catalog.cc:455] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "61f55bbae498460a874c2f6f0a2eb8ff" member_type: VOTER } }
I20260812 06:18:41.684055 26090 sys_catalog.cc:458] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:41.684569 26103 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:41.684857 25700 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:41.686724 26103 catalog_manager.cc:1383] Generated new cluster ID: 1258831501924495bd4e7c3a9fb7cefd
I20260812 06:18:41.686800 26103 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:41.711494 26103 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:41.712097 26103 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:41.721029 26103 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff: Generated new TSK 0
I20260812 06:18:41.721238 26103 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:41.749711 25700 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:41.751878 26114 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.751976 25700 server_base.cc:1061] running on GCE node
W20260812 06:18:41.752059 26117 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:41.751881 26115 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:41.752415 25700 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:41.752475 25700 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:41.752491 25700 hybrid_clock.cc:648] HybridClock initialized: now 1786515521752491 us; error 0 us; skew 500 ppm
I20260812 06:18:41.753561 25700 webserver.cc:533] Webserver started at http://127.25.25.1:38527/ using document root <none> and password file <none>
I20260812 06:18:41.753768 25700 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:41.753842 25700 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:41.753901 25700 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:41.754276 25700 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/instance:
uuid: "e57b4252d22c42d1a4db23d9a4a7b831"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-t7g5"
I20260812 06:18:41.755753 25700 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:41.756901 26126 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.757251 25700 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:41.757332 25700 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root
uuid: "e57b4252d22c42d1a4db23d9a4a7b831"
format_stamp: "Formatted at 2026-08-12 06:18:41 on dist-test-slave-t7g5"
I20260812 06:18:41.757400 25700 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:41.767570 25700 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:41.767959 25700 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:41.768270 25700 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:41.768772 25700 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:41.768812 25700 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.768846 25700 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:41.768859 25700 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:41.773135 25700 rpc_server.cc:307] RPC server started. Bound to: 127.25.25.1:39139
I20260812 06:18:41.773180 26224 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.25.25.1:39139 every 8 connection(s)
I20260812 06:18:41.782130 26226 heartbeater.cc:344] Connected to a master server at 127.25.25.62:43467
I20260812 06:18:41.782261 26226 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:41.782522 26226 heartbeater.cc:507] Master 127.25.25.62:43467 requested a full tablet report, sending...
I20260812 06:18:41.783334 26027 ts_manager.cc:194] Registered new tserver with Master: e57b4252d22c42d1a4db23d9a4a7b831 (127.25.25.1:39139)
I20260812 06:18:41.783915 25700 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010366912s
I20260812 06:18:41.784088 26027 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51634
I20260812 06:18:41.792029 26027 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51638:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:41.801543 26168 tablet_service.cc:1511] Processing CreateTablet for tablet 791e93f02a0e43cfa626969708bb1c06 (DEFAULT_TABLE table=heavy-update-compaction-test [id=2515a9a8ff3f45c88c2252b3fa0bc720]), partition=
I20260812 06:18:41.801877 26168 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 791e93f02a0e43cfa626969708bb1c06. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:41.804898 26249 tablet_bootstrap.cc:492] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Bootstrap starting.
I20260812 06:18:41.805830 26249 tablet_bootstrap.cc:654] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:41.807024 26249 tablet_bootstrap.cc:492] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: No bootstrap required, opened a new log
I20260812 06:18:41.807117 26249 ts_tablet_manager.cc:1403] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:41.807562 26249 raft_consensus.cc:359] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e57b4252d22c42d1a4db23d9a4a7b831" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 39139 } }
I20260812 06:18:41.807655 26249 raft_consensus.cc:385] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:41.807686 26249 raft_consensus.cc:740] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e57b4252d22c42d1a4db23d9a4a7b831, State: Initialized, Role: FOLLOWER
I20260812 06:18:41.807837 26249 consensus_queue.cc:260] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [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: "e57b4252d22c42d1a4db23d9a4a7b831" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 39139 } }
I20260812 06:18:41.807912 26249 raft_consensus.cc:399] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:41.807951 26249 raft_consensus.cc:493] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:41.807999 26249 raft_consensus.cc:3060] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:41.808748 26249 raft_consensus.cc:515] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e57b4252d22c42d1a4db23d9a4a7b831" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 39139 } }
I20260812 06:18:41.808887 26249 leader_election.cc:304] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [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: e57b4252d22c42d1a4db23d9a4a7b831; no voters: 
I20260812 06:18:41.809072 26249 leader_election.cc:290] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:41.809235 26256 raft_consensus.cc:2804] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:41.809376 26249 ts_tablet_manager.cc:1434] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:41.809453 26256 raft_consensus.cc:697] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 1 LEADER]: Becoming Leader. State: Replica: e57b4252d22c42d1a4db23d9a4a7b831, State: Running, Role: LEADER
I20260812 06:18:41.809466 26226 heartbeater.cc:499] Master 127.25.25.62:43467 was elected leader, sending a full tablet report...
I20260812 06:18:41.809621 26256 consensus_queue.cc:237] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [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: "e57b4252d22c42d1a4db23d9a4a7b831" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 39139 } }
I20260812 06:18:41.811122 26027 catalog_manager.cc:5719] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 reported cstate change: term changed from 0 to 1, leader changed from <none> to e57b4252d22c42d1a4db23d9a4a7b831 (127.25.25.1). New cstate: current_term: 1 leader_uuid: "e57b4252d22c42d1a4db23d9a4a7b831" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e57b4252d22c42d1a4db23d9a4a7b831" member_type: VOTER last_known_addr { host: "127.25.25.1" port: 39139 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:41.877470 25700 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.010s	sys 0.014s
I20260812 06:18:42.024415 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushMRSOp(791e93f02a0e43cfa626969708bb1c06): perf score=19.054940
I20260812 06:18:42.172354 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushMRSOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.148s	user 0.113s	sys 0.032s Metrics: {"bytes_written":8697369,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":106,"dirs.run_cpu_time_us":241,"dirs.run_wall_time_us":976,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":36356,"lbm_writes_lt_1ms":669,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1060}
I20260812 06:18:42.173194 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling LogGCOp(791e93f02a0e43cfa626969708bb1c06): free 20743880 bytes of WAL
I20260812 06:18:42.173643 26133 log_reader.cc:385] T 791e93f02a0e43cfa626969708bb1c06: removed 2 log segments from log reader
I20260812 06:18:42.173781 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000001 (ops 1-6)
I20260812 06:18:42.173835 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000002 (ops 7-11)
I20260812 06:18:42.178331 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: LogGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:18:42.178848 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:42.190421 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3610358,"delete_count":0,"lbm_write_time_us":4055,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:18:42.190876 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:42.316855 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.125s	user 0.068s	sys 0.049s Metrics: {"cfile_cache_miss":332,"cfile_cache_miss_bytes":16569855,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":481,"lbm_read_time_us":10390,"lbm_reads_lt_1ms":368,"lbm_write_time_us":17887,"lbm_writes_lt_1ms":343,"mutex_wait_us":37,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":331,"threads_started":5,"update_count":1500}
I20260812 06:18:42.317330 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:42.370133 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.053s	user 0.034s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17231,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.370582 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06): 16411393 bytes on disk
I20260812 06:18:42.370967 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06) 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:18:42.371356 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:42.390074 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.019s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.390673 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:42.544603 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.154s	user 0.089s	sys 0.064s 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":303,"lbm_read_time_us":12259,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22113,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:18:42.545135 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:42.589404 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.044s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14561,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.589907 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:42.601037 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3995,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.601776 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:42.737406 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.135s	user 0.106s	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":1096,"lbm_read_time_us":10488,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24799,"lbm_writes_lt_1ms":443,"mutex_wait_us":311,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:42.738098 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:42.772477 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.034s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12872,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.772951 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:42.783280 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.783802 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:42.912614 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.129s	user 0.097s	sys 0.026s 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":328,"lbm_read_time_us":8774,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24587,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:42.913144 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:42.972003 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.059s	user 0.034s	sys 0.011s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16230,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.972582 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:42.982971 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3911,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.983405 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:43.140512 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.157s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":278,"lbm_read_time_us":10720,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25989,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2000}
I20260812 06:18:43.141088 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:43.186103 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16585,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.186625 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:43.197204 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.197731 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:43.327991 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.130s	user 0.101s	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":917,"lbm_read_time_us":9797,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24541,"lbm_writes_lt_1ms":443,"mutex_wait_us":320,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:43.328521 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:43.374401 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.046s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15640,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.374985 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:43.388633 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.389228 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:43.513935 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.124s	user 0.100s	sys 0.024s 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":1344,"lbm_read_time_us":8245,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24774,"lbm_writes_lt_1ms":443,"mutex_wait_us":521,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:18:43.514639 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:43.551355 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14988,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:43.552009 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:43.573427 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.574002 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushMRSOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:43.612387 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushMRSOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.038s	user 0.019s	sys 0.007s Metrics: {"bytes_written":1316413,"cfile_init":1,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1242,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1667,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:43.613021 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=3.181125
I20260812 06:18:43.627992 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4307783,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:43.628533 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling LogGCOp(791e93f02a0e43cfa626969708bb1c06): free 129320517 bytes of WAL
I20260812 06:18:43.628808 26133 log_reader.cc:385] T 791e93f02a0e43cfa626969708bb1c06: removed 13 log segments from log reader
I20260812 06:18:43.628859 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000003 (ops 12-16)
I20260812 06:18:43.628911 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000004 (ops 17-21)
I20260812 06:18:43.628945 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000005 (ops 22-26)
I20260812 06:18:43.628978 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000006 (ops 27-30)
I20260812 06:18:43.629010 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000007 (ops 31-35)
I20260812 06:18:43.629041 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000008 (ops 36-40)
I20260812 06:18:43.629071 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000009 (ops 41-45)
I20260812 06:18:43.629101 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000010 (ops 46-50)
I20260812 06:18:43.629132 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000011 (ops 51-54)
I20260812 06:18:43.629160 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000012 (ops 55-59)
I20260812 06:18:43.629190 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000013 (ops 60-64)
I20260812 06:18:43.629220 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000014 (ops 65-69)
I20260812 06:18:43.629251 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000015 (ops 70-74)
I20260812 06:18:43.654990 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: LogGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.026s	user 0.002s	sys 0.023s Metrics: {}
I20260812 06:18:43.655543 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06): 492 bytes on disk
I20260812 06:18:43.656016 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:43.656466 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=3.181125
I20260812 06:18:43.675800 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.019s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4307789,"delete_count":0,"lbm_write_time_us":7009,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:18:43.676306 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:43.686381 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.686897 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:43.865432 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.178s	user 0.138s	sys 0.036s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979870,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":625,"lbm_read_time_us":12363,"lbm_reads_lt_1ms":775,"lbm_write_time_us":33775,"lbm_writes_lt_1ms":743,"mutex_wait_us":52,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":3712,"thread_start_us":81,"threads_started":1,"update_count":3500}
I20260812 06:18:43.866014 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:43.913591 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.047s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18432,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.914315 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:43.929828 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.930506 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:44.097620 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.167s	user 0.115s	sys 0.037s 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":1198,"lbm_read_time_us":11656,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28904,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2500}
I20260812 06:18:44.100926 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:44.153607 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.053s	user 0.028s	sys 0.010s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18255,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.154132 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:44.165129 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.165755 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:44.356974 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.191s	user 0.118s	sys 0.061s 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":302,"lbm_read_time_us":12874,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29142,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15616,"update_count":2500}
I20260812 06:18:44.357498 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:44.412545 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.055s	user 0.028s	sys 0.024s Metrics: {"bytes_written":16409908,"delete_count":0,"lbm_write_time_us":23923,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.413522 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:44.559193 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.145s	user 0.100s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672164,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":192,"lbm_read_time_us":13963,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":466,"lbm_write_time_us":23307,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:18:44.559834 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:44.589800 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.030s	user 0.030s	sys 0.000s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12817,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.590361 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:44.610416 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.611181 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:44.753935 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.142s	user 0.125s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":686,"lbm_read_time_us":8091,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28338,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:18:44.754688 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:44.796391 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.041s	user 0.030s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":18098,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.796918 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:44.808184 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3645,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.808971 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:44.939617 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.130s	user 0.098s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1553,"lbm_read_time_us":8639,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25038,"lbm_writes_lt_1ms":443,"mutex_wait_us":465,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:18:44.940357 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:44.990016 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.049s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15921,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:44.990644 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:45.002985 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4467,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.003999 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushMRSOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:45.031849 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushMRSOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":252,"dirs.run_wall_time_us":1407,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1372,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:45.032908 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling LogGCOp(791e93f02a0e43cfa626969708bb1c06): free 115943187 bytes of WAL
I20260812 06:18:45.033296 26133 log_reader.cc:385] T 791e93f02a0e43cfa626969708bb1c06: removed 11 log segments from log reader
I20260812 06:18:45.033382 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000016 (ops 75-79)
I20260812 06:18:45.033430 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000017 (ops 80-84)
I20260812 06:18:45.033464 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000018 (ops 85-89)
I20260812 06:18:45.033491 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000019 (ops 90-94)
I20260812 06:18:45.033526 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000020 (ops 95-99)
I20260812 06:18:45.033552 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000021 (ops 100-104)
I20260812 06:18:45.033584 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000022 (ops 105-109)
I20260812 06:18:45.033610 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000023 (ops 110-114)
I20260812 06:18:45.033643 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000024 (ops 115-119)
I20260812 06:18:45.033710 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000025 (ops 120-124)
I20260812 06:18:45.033736 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000026 (ops 125-129)
I20260812 06:18:45.060361 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: LogGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:18:45.060921 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06): 448 bytes on disk
I20260812 06:18:45.061501 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:18:45.062122 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=3.181125
I20260812 06:18:45.079288 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.017s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4575,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.079788 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:45.089826 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3630,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.090339 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:45.276674 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.186s	user 0.134s	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":826,"lbm_read_time_us":12986,"lbm_reads_lt_1ms":674,"lbm_write_time_us":35618,"lbm_writes_lt_1ms":643,"mutex_wait_us":331,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":81,"threads_started":1,"update_count":3000}
I20260812 06:18:45.277290 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:45.331061 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.054s	user 0.027s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17530,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.331784 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:45.343469 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4058,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.344122 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:45.515386 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.170s	user 0.127s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":275,"lbm_read_time_us":12350,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32279,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:45.517501 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=12.110812
I20260812 06:18:45.556397 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.039s	user 0.020s	sys 0.015s Metrics: {"bytes_written":13497198,"delete_count":0,"lbm_write_time_us":16849,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1645}
I20260812 06:18:45.557020 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.196750
I20260812 06:18:45.570096 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2912930,"delete_count":0,"lbm_write_time_us":3610,"lbm_writes_lt_1ms":74,"reinsert_count":0,"update_count":355}
I20260812 06:18:45.570595 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:45.732651 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.162s	user 0.098s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672256,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":611,"lbm_read_time_us":10530,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27445,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":442,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":31104,"update_count":2000}
I20260812 06:18:45.733498 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:45.779762 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.046s	user 0.023s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17774,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.780292 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:45.799333 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.019s	user 0.010s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.799867 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:46.000314 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.200s	user 0.143s	sys 0.052s 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":179,"lbm_read_time_us":13140,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33085,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":77824,"update_count":2500}
I20260812 06:18:46.000941 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:46.053337 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.052s	user 0.031s	sys 0.012s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":19815,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.054013 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:46.067656 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.068192 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:46.257241 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.189s	user 0.138s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774684,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":660,"lbm_read_time_us":11390,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29682,"lbm_writes_lt_1ms":543,"mutex_wait_us":292,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":33792,"update_count":2500}
I20260812 06:18:46.257845 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=14.095187
I20260812 06:18:46.308558 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.051s	user 0.035s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22176,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:46.309198 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:46.325728 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.016s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.326216 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:46.475482 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.149s	user 0.117s	sys 0.028s 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":1101,"lbm_read_time_us":8977,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30335,"lbm_writes_lt_1ms":543,"mutex_wait_us":456,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:18:46.476236 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=11.118625
I20260812 06:18:46.513868 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.037s	user 0.022s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16076,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:46.514495 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:46.528486 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.014s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4242,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.529100 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushMRSOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:46.570143 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushMRSOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.041s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":196,"dirs.run_wall_time_us":1359,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2301,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:46.571041 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06): 482 bytes on disk
I20260812 06:18:46.571625 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: UndoDeltaBlockGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.572386 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=3.181125
I20260812 06:18:46.589419 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":6788,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:46.589908 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling LogGCOp(791e93f02a0e43cfa626969708bb1c06): free 124710570 bytes of WAL
I20260812 06:18:46.590107 26133 log_reader.cc:385] T 791e93f02a0e43cfa626969708bb1c06: removed 12 log segments from log reader
I20260812 06:18:46.590149 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000027 (ops 130-134)
I20260812 06:18:46.590179 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000028 (ops 135-139)
I20260812 06:18:46.590209 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000029 (ops 140-144)
I20260812 06:18:46.590240 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000030 (ops 145-149)
I20260812 06:18:46.590273 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000031 (ops 150-154)
I20260812 06:18:46.590306 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000032 (ops 155-159)
I20260812 06:18:46.590337 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000033 (ops 160-164)
I20260812 06:18:46.590369 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000034 (ops 165-169)
I20260812 06:18:46.590401 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000035 (ops 170-174)
I20260812 06:18:46.590432 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000036 (ops 175-179)
I20260812 06:18:46.590464 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000037 (ops 180-184)
I20260812 06:18:46.590497 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000038 (ops 185-189)
I20260812 06:18:46.611701 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: LogGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.022s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:46.612212 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:46.644105 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.032s	user 0.013s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6332,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:46.644740 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling LogGCOp(791e93f02a0e43cfa626969708bb1c06): free 12017954 bytes of WAL
I20260812 06:18:46.644966 26133 log_reader.cc:385] T 791e93f02a0e43cfa626969708bb1c06: removed 1 log segments from log reader
I20260812 06:18:46.645010 26133 log.cc:1079] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: Deleting log segment in path: /tmp/dist-test-task_DbYn_/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515516185950-25700-0/minicluster-data/ts-0-root/wals/791e93f02a0e43cfa626969708bb1c06/wal-000000039 (ops 190-194)
I20260812 06:18:46.647071 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: LogGCOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:46.647393 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=2.188937
I20260812 06:18:46.658005 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.658457 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06): perf score=1.000000
I20260812 06:18:46.810253 25700 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.933s	user 1.808s	sys 0.144s
I20260812 06:18:46.888068 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: MajorDeltaCompactionOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.229s	user 0.160s	sys 0.067s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"lbm_read_time_us":15938,"lbm_reads_lt_1ms":771,"lbm_write_time_us":38450,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"update_count":3500}
I20260812 06:18:46.888530 26229 maintenance_manager.cc:419] P e57b4252d22c42d1a4db23d9a4a7b831: Scheduling FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06): perf score=10.126437
I20260812 06:18:46.909155 25700 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.098s	user 0.000s	sys 0.000s
I20260812 06:18:46.909725 25700 tablet_server.cc:179] TabletServer@127.25.25.1:0 shutting down...
I20260812 06:18:46.921065 26133 maintenance_manager.cc:643] P e57b4252d22c42d1a4db23d9a4a7b831: FlushDeltaMemStoresOp(791e93f02a0e43cfa626969708bb1c06) complete. Timing: real 0.032s	user 0.006s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13873,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.921885 25700 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:46.922180 25700 tablet_replica.cc:333] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831: stopping tablet replica
I20260812 06:18:46.922313 25700 raft_consensus.cc:2243] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.922461 25700 raft_consensus.cc:2272] T 791e93f02a0e43cfa626969708bb1c06 P e57b4252d22c42d1a4db23d9a4a7b831 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.936098 25700 tablet_server.cc:196] TabletServer@127.25.25.1:0 shutdown complete.
I20260812 06:18:46.948529 25700 master.cc:562] Master@127.25.25.62:43467 shutting down...
I20260812 06:18:46.952615 25700 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:46.952833 25700 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:46.952913 25700 tablet_replica.cc:333] T 00000000000000000000000000000000 P 61f55bbae498460a874c2f6f0a2eb8ff: stopping tablet replica
I20260812 06:18:46.965574 25700 master.cc:584] Master@127.25.25.62:43467 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5402 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10847 ms total)

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