[==========] 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:40.209838 18694 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.65.190:40741
I20260812 06:18:40.210856 18694 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:40.211467 18694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.217798 18706 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:40.217880 18704 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:40.217880 18694 server_base.cc:1061] running on GCE node
W20260812 06:18:40.218183 18712 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:40.218679 18694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.218801 18694 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:40.218847 18694 hybrid_clock.cc:648] HybridClock initialized: now 1786515520218844 us; error 0 us; skew 500 ppm
I20260812 06:18:40.220645 18694 webserver.cc:533] Webserver started at http://127.18.65.190:39275/ using document root <none> and password file <none>
I20260812 06:18:40.221266 18694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.221326 18694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.221580 18694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.223229 18694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/master-0-root/instance:
uuid: "ecf533b89d074659b16dbe67844e587c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-ffrd"
I20260812 06:18:40.226729 18694 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:40.228729 18721 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:40.229745 18694 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:40.229907 18694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/master-0-root
uuid: "ecf533b89d074659b16dbe67844e587c"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-ffrd"
I20260812 06:18:40.230005 18694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-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:40.247782 18694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.248406 18694 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:40.248584 18694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.256459 18694 rpc_server.cc:307] RPC server started. Bound to: 127.18.65.190:40741
I20260812 06:18:40.256464 18807 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.65.190:40741 every 8 connection(s)
I20260812 06:18:40.258628 18810 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:40.263924 18810 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: Bootstrap starting.
I20260812 06:18:40.266229 18810 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.267125 18810 log.cc:826] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:40.268795 18810 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: No bootstrap required, opened a new log
I20260812 06:18:40.271723 18810 raft_consensus.cc:359] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER }
I20260812 06:18:40.271899 18810 raft_consensus.cc:385] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.271942 18810 raft_consensus.cc:740] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ecf533b89d074659b16dbe67844e587c, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.272454 18810 consensus_queue.cc:260] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [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: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER }
I20260812 06:18:40.272584 18810 raft_consensus.cc:399] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.272622 18810 raft_consensus.cc:493] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.272702 18810 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.273540 18810 raft_consensus.cc:515] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER }
I20260812 06:18:40.273926 18810 leader_election.cc:304] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [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: ecf533b89d074659b16dbe67844e587c; no voters: 
I20260812 06:18:40.274185 18810 leader_election.cc:290] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.274322 18817 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.274602 18817 raft_consensus.cc:697] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 1 LEADER]: Becoming Leader. State: Replica: ecf533b89d074659b16dbe67844e587c, State: Running, Role: LEADER
I20260812 06:18:40.275070 18817 consensus_queue.cc:237] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [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: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER }
I20260812 06:18:40.275238 18810 sys_catalog.cc:565] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:40.276893 18821 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [sys.catalog]: SysCatalogTable state changed. Reason: New leader ecf533b89d074659b16dbe67844e587c. Latest consensus state: current_term: 1 leader_uuid: "ecf533b89d074659b16dbe67844e587c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER } }
I20260812 06:18:40.276978 18818 sys_catalog.cc:455] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ecf533b89d074659b16dbe67844e587c" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ecf533b89d074659b16dbe67844e587c" member_type: VOTER } }
I20260812 06:18:40.277046 18821 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.277077 18818 sys_catalog.cc:458] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:40.277472 18831 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:40.277691 18694 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:40.280149 18831 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:40.285343 18831 catalog_manager.cc:1383] Generated new cluster ID: ab0d5aad252b4b96a3881b661beb723d
I20260812 06:18:40.285429 18831 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:40.303035 18831 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:40.304654 18831 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:40.313534 18831 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: Generated new TSK 0
I20260812 06:18:40.314366 18831 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:40.342648 18694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:40.345713 18845 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:40.345876 18694 server_base.cc:1061] running on GCE node
W20260812 06:18:40.345944 18848 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:40.345734 18844 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:40.346256 18694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:40.346323 18694 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:40.346349 18694 hybrid_clock.cc:648] HybridClock initialized: now 1786515520346348 us; error 0 us; skew 500 ppm
I20260812 06:18:40.347363 18694 webserver.cc:533] Webserver started at http://127.18.65.129:45855/ using document root <none> and password file <none>
I20260812 06:18:40.347559 18694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:40.347632 18694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:40.347714 18694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:40.348183 18694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/instance:
uuid: "848fce5a8be6475da9fd5c61a1ae1981"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-ffrd"
I20260812 06:18:40.349895 18694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:40.350908 18857 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:40.351177 18694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:40.351259 18694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root
uuid: "848fce5a8be6475da9fd5c61a1ae1981"
format_stamp: "Formatted at 2026-08-12 06:18:40 on dist-test-slave-ffrd"
I20260812 06:18:40.351357 18694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-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:40.367319 18694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:40.367812 18694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:40.368366 18694 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:40.369406 18694 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:40.369477 18694 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.369570 18694 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:40.369609 18694 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:40.376659 18694 rpc_server.cc:307] RPC server started. Bound to: 127.18.65.129:44517
I20260812 06:18:40.377635 18967 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.65.129:44517 every 8 connection(s)
I20260812 06:18:40.387413 18968 heartbeater.cc:344] Connected to a master server at 127.18.65.190:40741
I20260812 06:18:40.387696 18968 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:40.388160 18968 heartbeater.cc:507] Master 127.18.65.190:40741 requested a full tablet report, sending...
I20260812 06:18:40.389755 18752 ts_manager.cc:194] Registered new tserver with Master: 848fce5a8be6475da9fd5c61a1ae1981 (127.18.65.129:44517)
I20260812 06:18:40.389993 18694 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012546605s
I20260812 06:18:40.391336 18752 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54548
I20260812 06:18:40.399941 18752 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54558:
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:40.417220 18910 tablet_service.cc:1511] Processing CreateTablet for tablet 5a20d9fc2e5b43689cf8a7f13e7eb099 (DEFAULT_TABLE table=heavy-update-compaction-test [id=32e0068256ab4b42b2a02848c39a8362]), partition=
I20260812 06:18:40.417757 18910 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5a20d9fc2e5b43689cf8a7f13e7eb099. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:40.420003 18987 tablet_bootstrap.cc:492] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Bootstrap starting.
I20260812 06:18:40.421209 18987 tablet_bootstrap.cc:654] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:40.422377 18987 tablet_bootstrap.cc:492] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: No bootstrap required, opened a new log
I20260812 06:18:40.422508 18987 ts_tablet_manager.cc:1403] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:40.423197 18987 raft_consensus.cc:359] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848fce5a8be6475da9fd5c61a1ae1981" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 44517 } }
I20260812 06:18:40.423331 18987 raft_consensus.cc:385] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:40.423380 18987 raft_consensus.cc:740] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 848fce5a8be6475da9fd5c61a1ae1981, State: Initialized, Role: FOLLOWER
I20260812 06:18:40.423527 18987 consensus_queue.cc:260] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [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: "848fce5a8be6475da9fd5c61a1ae1981" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 44517 } }
I20260812 06:18:40.423642 18987 raft_consensus.cc:399] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:40.423692 18987 raft_consensus.cc:493] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:40.423743 18987 raft_consensus.cc:3060] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:40.424476 18987 raft_consensus.cc:515] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848fce5a8be6475da9fd5c61a1ae1981" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 44517 } }
I20260812 06:18:40.424641 18987 leader_election.cc:304] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [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: 848fce5a8be6475da9fd5c61a1ae1981; no voters: 
I20260812 06:18:40.424876 18987 leader_election.cc:290] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:40.425215 18991 raft_consensus.cc:2804] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:40.425257 18987 ts_tablet_manager.cc:1434] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:40.425696 18968 heartbeater.cc:499] Master 127.18.65.190:40741 was elected leader, sending a full tablet report...
I20260812 06:18:40.425734 18991 raft_consensus.cc:697] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 1 LEADER]: Becoming Leader. State: Replica: 848fce5a8be6475da9fd5c61a1ae1981, State: Running, Role: LEADER
I20260812 06:18:40.425902 18991 consensus_queue.cc:237] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [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: "848fce5a8be6475da9fd5c61a1ae1981" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 44517 } }
I20260812 06:18:40.429040 18752 catalog_manager.cc:5719] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 reported cstate change: term changed from 0 to 1, leader changed from <none> to 848fce5a8be6475da9fd5c61a1ae1981 (127.18.65.129). New cstate: current_term: 1 leader_uuid: "848fce5a8be6475da9fd5c61a1ae1981" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "848fce5a8be6475da9fd5c61a1ae1981" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 44517 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:40.492625 18694 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.020s	sys 0.004s
I20260812 06:18:40.627910 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=19.054940
I20260812 06:18:40.789757 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.161s	user 0.121s	sys 0.039s Metrics: {"bytes_written":9681945,"cfile_init":1,"compiler_manager_pool.queue_time_us":379,"delete_count":0,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":194,"dirs.run_wall_time_us":952,"drs_written":1,"lbm_read_time_us":117,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38691,"lbm_writes_lt_1ms":693,"mutex_wait_us":216,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":178304,"thread_start_us":126,"threads_started":1,"update_count":1180}
I20260812 06:18:40.791132 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): free 20743880 bytes of WAL
I20260812 06:18:40.791639 18867 log_reader.cc:385] T 5a20d9fc2e5b43689cf8a7f13e7eb099: removed 2 log segments from log reader
I20260812 06:18:40.791795 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000001 (ops 1-6)
I20260812 06:18:40.791882 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000002 (ops 7-11)
I20260812 06:18:40.798834 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.008s	user 0.000s	sys 0.006s Metrics: {}
I20260812 06:18:40.799428 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): 16411392 bytes on disk
I20260812 06:18:40.800158 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.800755 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.196750
I20260812 06:18:40.827523 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.027s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3036010,"delete_count":0,"lbm_write_time_us":3621,"lbm_writes_lt_1ms":77,"reinsert_count":0,"update_count":370}
I20260812 06:18:40.828006 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:40.844138 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6347,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:40.844610 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:40.989948 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.145s	user 0.126s	sys 0.019s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672360,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":708,"lbm_read_time_us":10610,"lbm_reads_lt_1ms":469,"lbm_write_time_us":24813,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3200,"thread_start_us":313,"threads_started":5,"update_count":2000}
I20260812 06:18:40.990411 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:41.038745 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.048s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16982,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.039191 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:41.050472 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4342,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.051110 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:41.170696 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.119s	user 0.100s	sys 0.017s 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":217,"lbm_read_time_us":8597,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24554,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2000}
I20260812 06:18:41.171145 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:41.222009 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.051s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16308,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.222461 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:41.233484 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4277,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.234090 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:41.357437 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.123s	user 0.102s	sys 0.020s 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":1186,"lbm_read_time_us":10199,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24224,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:41.358098 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:41.409940 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.052s	user 0.019s	sys 0.032s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18883,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.410543 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:41.427426 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.017s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.427863 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:41.583294 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.155s	user 0.098s	sys 0.056s 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":963,"lbm_read_time_us":11875,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27425,"lbm_writes_lt_1ms":443,"mutex_wait_us":294,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:18:41.586942 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:41.635605 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.048s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16990,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.636190 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:41.648828 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4514,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.649435 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:41.773182 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.124s	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":796,"lbm_read_time_us":10685,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22684,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:18:41.773897 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:41.811184 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.037s	user 0.032s	sys 0.001s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15431,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:41.811709 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:41.822824 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4291,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:41.823550 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:41.957593 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.134s	user 0.114s	sys 0.019s 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":350,"lbm_read_time_us":9684,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26353,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:41.958271 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=10.126437
I20260812 06:18:42.003412 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.045s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20807,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:42.003887 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:42.016106 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4420,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.016618 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:42.048091 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.031s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":84,"dirs.run_cpu_time_us":272,"dirs.run_wall_time_us":1159,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2090,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:42.049046 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): free 115943177 bytes of WAL
I20260812 06:18:42.049291 18867 log_reader.cc:385] T 5a20d9fc2e5b43689cf8a7f13e7eb099: removed 11 log segments from log reader
I20260812 06:18:42.049374 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000003 (ops 12-16)
I20260812 06:18:42.049424 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000004 (ops 17-21)
I20260812 06:18:42.049484 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000005 (ops 22-26)
I20260812 06:18:42.049525 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000006 (ops 27-31)
I20260812 06:18:42.049566 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000007 (ops 32-36)
I20260812 06:18:42.049602 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000008 (ops 37-41)
I20260812 06:18:42.049639 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000009 (ops 42-46)
I20260812 06:18:42.049678 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000010 (ops 47-51)
I20260812 06:18:42.049715 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000011 (ops 52-56)
I20260812 06:18:42.049752 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000012 (ops 57-61)
I20260812 06:18:42.049789 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000013 (ops 62-66)
I20260812 06:18:42.078429 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.029s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:18:42.078917 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=3.181125
I20260812 06:18:42.096709 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7054,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:42.097230 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:42.106657 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3789,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:42.107070 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:42.296442 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.189s	user 0.141s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3754,"dirs.run_cpu_time_us":590,"dirs.run_wall_time_us":3476,"lbm_read_time_us":14476,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37197,"lbm_writes_lt_1ms":643,"mutex_wait_us":3310,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:18:42.297113 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:42.352087 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.055s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18247,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.352653 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): 448 bytes on disk
I20260812 06:18:42.353143 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":101,"lbm_reads_lt_1ms":4}
I20260812 06:18:42.353602 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:42.364395 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.005s	sys 0.003s 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:42.365175 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:42.526361 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.161s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":430,"lbm_read_time_us":11400,"lbm_reads_lt_1ms":568,"lbm_write_time_us":29579,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:18:42.527081 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:42.585498 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.058s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22650,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.586031 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:42.598062 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.001s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4468,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.598528 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:42.801147 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.202s	user 0.124s	sys 0.069s 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":335,"lbm_read_time_us":14258,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33903,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:42.801879 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:42.868680 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.067s	user 0.026s	sys 0.025s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25050,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:42.869154 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:42.880827 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:42.881528 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:43.060858 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.179s	user 0.123s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1083,"lbm_read_time_us":13615,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33406,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":62080,"update_count":2500}
I20260812 06:18:43.061631 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:43.125728 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.064s	user 0.025s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20717,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.126317 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:43.138180 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4505,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.138674 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:43.320875 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.182s	user 0.123s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":130,"lbm_read_time_us":15185,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31855,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:18:43.321674 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=11.118625
I20260812 06:18:43.360273 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.038s	user 0.020s	sys 0.015s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15752,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:43.361660 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:43.390690 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.029s	user 0.014s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6617,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.391122 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:43.401604 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4191,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.402061 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:43.595096 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.193s	user 0.106s	sys 0.075s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":397,"lbm_read_time_us":14839,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31856,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:43.595625 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:43.662696 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.067s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22618,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:43.663218 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:43.674408 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:43.674911 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:43.722819 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.048s	user 0.029s	sys 0.004s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":93,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1141,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1708,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32,"spinlock_wait_cycles":9984}
I20260812 06:18:43.723515 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): free 133024372 bytes of WAL
I20260812 06:18:43.723731 18867 log_reader.cc:385] T 5a20d9fc2e5b43689cf8a7f13e7eb099: removed 13 log segments from log reader
I20260812 06:18:43.723771 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000014 (ops 67-71)
I20260812 06:18:43.723800 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000015 (ops 72-76)
I20260812 06:18:43.723867 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000016 (ops 77-80)
I20260812 06:18:43.723910 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000017 (ops 81-85)
I20260812 06:18:43.723951 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000018 (ops 86-90)
I20260812 06:18:43.723991 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000019 (ops 91-95)
I20260812 06:18:43.724033 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000020 (ops 96-100)
I20260812 06:18:43.724072 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000021 (ops 101-105)
I20260812 06:18:43.724112 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000022 (ops 106-110)
I20260812 06:18:43.724150 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000023 (ops 111-115)
I20260812 06:18:43.724190 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000024 (ops 116-120)
I20260812 06:18:43.724231 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000025 (ops 121-125)
I20260812 06:18:43.724269 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000026 (ops 126-130)
I20260812 06:18:43.755200 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:43.755662 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=3.181125
I20260812 06:18:43.772470 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.017s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4827,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:43.773101 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:43.783203 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3949,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:43.783648 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:44.044751 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.261s	user 0.162s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979739,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":828,"lbm_read_time_us":17987,"lbm_reads_lt_1ms":774,"lbm_write_time_us":45179,"lbm_writes_lt_1ms":743,"mutex_wait_us":358,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2048,"thread_start_us":82,"threads_started":1,"update_count":3500}
I20260812 06:18:44.045588 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=18.063937
I20260812 06:18:44.114862 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.069s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":29418,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:44.115381 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:44.127038 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4317,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.127565 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): 492 bytes on disk
I20260812 06:18:44.128214 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: UndoDeltaBlockGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":127,"lbm_reads_lt_1ms":4}
I20260812 06:18:44.129204 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:44.327039 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.198s	user 0.148s	sys 0.048s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1461,"lbm_read_time_us":17227,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35482,"lbm_writes_lt_1ms":643,"mutex_wait_us":546,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":3000}
I20260812 06:18:44.327694 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:44.373013 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.045s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20044,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.373699 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:44.397984 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.024s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.398509 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:44.409510 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.410179 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:44.578100 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.168s	user 0.121s	sys 0.046s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":294,"lbm_read_time_us":13135,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34166,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:18:44.578703 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:44.628914 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.050s	user 0.037s	sys 0.009s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.629508 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:44.647505 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.018s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:44.648195 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:44.806551 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.158s	user 0.109s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":243,"lbm_read_time_us":9915,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28838,"lbm_writes_lt_1ms":543,"mutex_wait_us":50,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:44.807366 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:44.854241 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.047s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20847,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:44.854874 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:45.019279 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.164s	user 0.116s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":216,"lbm_read_time_us":11460,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25754,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2000}
I20260812 06:18:45.020022 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=14.095187
I20260812 06:18:45.068290 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.048s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20863,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:45.068913 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:45.081568 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:45.082162 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:45.116775 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushMRSOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.034s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1178,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1531,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:45.117601 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099): free 112239554 bytes of WAL
I20260812 06:18:45.117873 18867 log_reader.cc:385] T 5a20d9fc2e5b43689cf8a7f13e7eb099: removed 11 log segments from log reader
I20260812 06:18:45.117954 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000027 (ops 131-135)
I20260812 06:18:45.118012 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000028 (ops 136-140)
I20260812 06:18:45.118069 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000029 (ops 141-145)
I20260812 06:18:45.118113 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000030 (ops 146-150)
I20260812 06:18:45.118153 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000031 (ops 151-155)
I20260812 06:18:45.118193 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000032 (ops 156-160)
I20260812 06:18:45.118233 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000033 (ops 161-165)
I20260812 06:18:45.118273 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000034 (ops 166-170)
I20260812 06:18:45.118312 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000035 (ops 171-175)
I20260812 06:18:45.118353 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000036 (ops 176-180)
I20260812 06:18:45.118391 18867 log.cc:1079] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/5a20d9fc2e5b43689cf8a7f13e7eb099/wal-000000037 (ops 181-184)
I20260812 06:18:45.146711 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: LogGCOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:45.147267 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=3.181125
I20260812 06:18:45.165292 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.018s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":5397,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:45.165724 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=2.188937
I20260812 06:18:45.175820 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3904,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:45.176364 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:45.419081 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.243s	user 0.143s	sys 0.096s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":246,"lbm_read_time_us":18384,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39916,"lbm_writes_lt_1ms":743,"mutex_wait_us":68,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:18:45.419920 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=18.063937
I20260812 06:18:45.478243 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: FlushDeltaMemStoresOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.058s	user 0.041s	sys 0.016s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":26100,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:18:45.478754 18971 maintenance_manager.cc:419] P 848fce5a8be6475da9fd5c61a1ae1981: Scheduling MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099): perf score=1.000000
I20260812 06:18:45.496372 18694 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.004s	user 1.886s	sys 0.119s
I20260812 06:18:45.590664 18694 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.094s	user 0.003s	sys 0.000s
I20260812 06:18:45.591498 18694 tablet_server.cc:179] TabletServer@127.18.65.129:0 shutting down...
I20260812 06:18:45.647948 18867 maintenance_manager.cc:643] P 848fce5a8be6475da9fd5c61a1ae1981: MajorDeltaCompactionOp(5a20d9fc2e5b43689cf8a7f13e7eb099) complete. Timing: real 0.169s	user 0.141s	sys 0.028s Metrics: {"cfile_cache_miss":531,"cfile_cache_miss_bytes":24774571,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":525,"lbm_read_time_us":15242,"lbm_reads_lt_1ms":563,"lbm_write_time_us":29352,"lbm_writes_lt_1ms":543,"mutex_wait_us":137,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2500}
I20260812 06:18:45.648769 18694 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:45.649335 18694 tablet_replica.cc:333] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981: stopping tablet replica
I20260812 06:18:45.649621 18694 raft_consensus.cc:2243] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.649868 18694 raft_consensus.cc:2272] T 5a20d9fc2e5b43689cf8a7f13e7eb099 P 848fce5a8be6475da9fd5c61a1ae1981 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.667128 18694 tablet_server.cc:196] TabletServer@127.18.65.129:0 shutdown complete.
I20260812 06:18:45.695185 18694 master.cc:562] Master@127.18.65.190:40741 shutting down...
I20260812 06:18:45.699334 18694 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:45.699563 18694 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:45.699661 18694 tablet_replica.cc:333] T 00000000000000000000000000000000 P ecf533b89d074659b16dbe67844e587c: stopping tablet replica
I20260812 06:18:45.712754 18694 master.cc:584] Master@127.18.65.190:40741 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5598 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:45.822784 18694 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.65.190:45733
I20260812 06:18:45.823246 18694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.825546 19017 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:45.825608 18694 server_base.cc:1061] running on GCE node
W20260812 06:18:45.825625 19018 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:45.825683 19020 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:45.825994 18694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.826040 18694 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:45.826056 18694 hybrid_clock.cc:648] HybridClock initialized: now 1786515525826055 us; error 0 us; skew 500 ppm
I20260812 06:18:45.826865 18694 webserver.cc:533] Webserver started at http://127.18.65.190:37397/ using document root <none> and password file <none>
I20260812 06:18:45.827020 18694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.827065 18694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.827117 18694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.827476 18694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/master-0-root/instance:
uuid: "ca0fc47d4c9742da8630dcdd61274de5"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-ffrd"
I20260812 06:18:45.829012 18694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:45.829912 19027 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:45.830154 18694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:45.830246 18694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/master-0-root
uuid: "ca0fc47d4c9742da8630dcdd61274de5"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-ffrd"
I20260812 06:18:45.830335 18694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-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:45.851339 18694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.851783 18694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.856160 18694 rpc_server.cc:307] RPC server started. Bound to: 127.18.65.190:45733
I20260812 06:18:45.859102 19127 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.65.190:45733 every 8 connection(s)
I20260812 06:18:45.859612 19129 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:45.861426 19129 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5: Bootstrap starting.
I20260812 06:18:45.862213 19129 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.863222 19129 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5: No bootstrap required, opened a new log
I20260812 06:18:45.863633 19129 raft_consensus.cc:359] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER }
I20260812 06:18:45.863725 19129 raft_consensus.cc:385] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.863749 19129 raft_consensus.cc:740] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: ca0fc47d4c9742da8630dcdd61274de5, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.863948 19129 consensus_queue.cc:260] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [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: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER }
I20260812 06:18:45.864022 19129 raft_consensus.cc:399] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.864078 19129 raft_consensus.cc:493] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.864143 19129 raft_consensus.cc:3060] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.864848 19129 raft_consensus.cc:515] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER }
I20260812 06:18:45.865020 19129 leader_election.cc:304] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [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: ca0fc47d4c9742da8630dcdd61274de5; no voters: 
I20260812 06:18:45.865238 19129 leader_election.cc:290] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.865374 19133 raft_consensus.cc:2804] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.865655 19133 raft_consensus.cc:697] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 1 LEADER]: Becoming Leader. State: Replica: ca0fc47d4c9742da8630dcdd61274de5, State: Running, Role: LEADER
I20260812 06:18:45.865757 19129 sys_catalog.cc:565] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:45.865788 19133 consensus_queue.cc:237] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [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: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER }
I20260812 06:18:45.866219 19134 sys_catalog.cc:455] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "ca0fc47d4c9742da8630dcdd61274de5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER } }
I20260812 06:18:45.866241 19135 sys_catalog.cc:455] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader ca0fc47d4c9742da8630dcdd61274de5. Latest consensus state: current_term: 1 leader_uuid: "ca0fc47d4c9742da8630dcdd61274de5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "ca0fc47d4c9742da8630dcdd61274de5" member_type: VOTER } }
I20260812 06:18:45.866460 19135 sys_catalog.cc:458] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.866451 19134 sys_catalog.cc:458] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:45.866972 19145 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:45.867915 19145 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:45.868137 18694 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:45.869757 19145 catalog_manager.cc:1383] Generated new cluster ID: 0edc1ba4cf5642bdbb059a7f27650bb9
I20260812 06:18:45.869814 19145 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:45.887513 19145 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:45.888087 19145 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:45.896072 19145 catalog_manager.cc:6092] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5: Generated new TSK 0
I20260812 06:18:45.896250 19145 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:45.900527 18694 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:45.902455 19159 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:45.902489 19163 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:45.902487 19160 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:45.902710 18694 server_base.cc:1061] running on GCE node
I20260812 06:18:45.902885 18694 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:45.902932 18694 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:45.902948 18694 hybrid_clock.cc:648] HybridClock initialized: now 1786515525902948 us; error 0 us; skew 500 ppm
I20260812 06:18:45.903839 18694 webserver.cc:533] Webserver started at http://127.18.65.129:46411/ using document root <none> and password file <none>
I20260812 06:18:45.903976 18694 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:45.904022 18694 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:45.904072 18694 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:45.904415 18694 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/instance:
uuid: "2dbecaaee34c4d7e94791dcd4a100ce2"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-ffrd"
I20260812 06:18:45.905963 18694 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:45.906960 19173 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:45.907279 18694 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:45.907348 18694 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root
uuid: "2dbecaaee34c4d7e94791dcd4a100ce2"
format_stamp: "Formatted at 2026-08-12 06:18:45 on dist-test-slave-ffrd"
I20260812 06:18:45.907446 18694 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-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:45.920560 18694 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:45.920897 18694 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:45.921242 18694 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:45.921692 18694 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:45.921756 18694 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.921814 18694 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:45.921849 18694 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:45.926049 18694 rpc_server.cc:307] RPC server started. Bound to: 127.18.65.129:37333
I20260812 06:18:45.927138 19279 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.65.129:37333 every 8 connection(s)
I20260812 06:18:45.935389 19281 heartbeater.cc:344] Connected to a master server at 127.18.65.190:45733
I20260812 06:18:45.935514 19281 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:45.935739 19281 heartbeater.cc:507] Master 127.18.65.190:45733 requested a full tablet report, sending...
I20260812 06:18:45.936409 19056 ts_manager.cc:194] Registered new tserver with Master: 2dbecaaee34c4d7e94791dcd4a100ce2 (127.18.65.129:37333)
I20260812 06:18:45.936723 18694 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010017456s
I20260812 06:18:45.937474 19056 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42976
I20260812 06:18:45.943783 19056 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42988:
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:45.952690 19218 tablet_service.cc:1511] Processing CreateTablet for tablet fece2f8ed12d4ac0b56af146f44fdbd5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=c82abb565a2a4192aab29319c3fcb69b]), partition=
I20260812 06:18:45.952989 19218 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet fece2f8ed12d4ac0b56af146f44fdbd5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:45.955056 19305 tablet_bootstrap.cc:492] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Bootstrap starting.
I20260812 06:18:45.955845 19305 tablet_bootstrap.cc:654] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:45.956828 19305 tablet_bootstrap.cc:492] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: No bootstrap required, opened a new log
I20260812 06:18:45.956971 19305 ts_tablet_manager.cc:1403] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:45.957350 19305 raft_consensus.cc:359] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2dbecaaee34c4d7e94791dcd4a100ce2" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 37333 } }
I20260812 06:18:45.957463 19305 raft_consensus.cc:385] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:45.957508 19305 raft_consensus.cc:740] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2dbecaaee34c4d7e94791dcd4a100ce2, State: Initialized, Role: FOLLOWER
I20260812 06:18:45.957647 19305 consensus_queue.cc:260] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [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: "2dbecaaee34c4d7e94791dcd4a100ce2" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 37333 } }
I20260812 06:18:45.957744 19305 raft_consensus.cc:399] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:45.957785 19305 raft_consensus.cc:493] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:45.957834 19305 raft_consensus.cc:3060] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:45.958649 19305 raft_consensus.cc:515] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2dbecaaee34c4d7e94791dcd4a100ce2" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 37333 } }
I20260812 06:18:45.958787 19305 leader_election.cc:304] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [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: 2dbecaaee34c4d7e94791dcd4a100ce2; no voters: 
I20260812 06:18:45.959013 19305 leader_election.cc:290] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:45.959137 19309 raft_consensus.cc:2804] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:45.959368 19305 ts_tablet_manager.cc:1434] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:45.959370 19281 heartbeater.cc:499] Master 127.18.65.190:45733 was elected leader, sending a full tablet report...
I20260812 06:18:45.959369 19309 raft_consensus.cc:697] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 1 LEADER]: Becoming Leader. State: Replica: 2dbecaaee34c4d7e94791dcd4a100ce2, State: Running, Role: LEADER
I20260812 06:18:45.959575 19309 consensus_queue.cc:237] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [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: "2dbecaaee34c4d7e94791dcd4a100ce2" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 37333 } }
I20260812 06:18:45.960805 19056 catalog_manager.cc:5719] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 reported cstate change: term changed from 0 to 1, leader changed from <none> to 2dbecaaee34c4d7e94791dcd4a100ce2 (127.18.65.129). New cstate: current_term: 1 leader_uuid: "2dbecaaee34c4d7e94791dcd4a100ce2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2dbecaaee34c4d7e94791dcd4a100ce2" member_type: VOTER last_known_addr { host: "127.18.65.129" port: 37333 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:46.023891 18694 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.007s	sys 0.016s
I20260812 06:18:46.177778 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=19.054940
I20260812 06:18:46.341004 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.163s	user 0.111s	sys 0.048s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":76,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":688,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42088,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:46.341694 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): free 20743831 bytes of WAL
I20260812 06:18:46.341971 19185 log_reader.cc:385] T fece2f8ed12d4ac0b56af146f44fdbd5: removed 2 log segments from log reader
I20260812 06:18:46.342052 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000001 (ops 1-6)
I20260812 06:18:46.342108 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000002 (ops 7-11)
I20260812 06:18:46.346637 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:18:46.347054 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:46.360689 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4853,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.361153 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:46.537070 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.176s	user 0.114s	sys 0.061s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":827,"lbm_read_time_us":11179,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29285,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":390,"threads_started":5,"update_count":2000}
I20260812 06:18:46.537695 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): 16411393 bytes on disk
I20260812 06:18:46.538201 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:18:46.538611 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:46.578598 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.040s	user 0.024s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17966,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.579363 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:46.592448 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.013s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4555,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.593051 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:46.724884 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.132s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":229,"lbm_read_time_us":9608,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26409,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2000}
I20260812 06:18:46.725621 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:46.762846 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.037s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15446,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.763320 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:46.774909 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:46.775414 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:46.911561 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.136s	user 0.116s	sys 0.016s 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":232,"lbm_read_time_us":10631,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24966,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":2000}
I20260812 06:18:46.912160 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:46.950397 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.038s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16519,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:46.950870 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:47.057514 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.106s	user 0.099s	sys 0.008s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569745,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":283,"lbm_read_time_us":7835,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19140,"lbm_writes_lt_1ms":343,"mutex_wait_us":35,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":1500}
I20260812 06:18:47.058115 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:47.105898 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.048s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16557,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.106320 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.117895 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4520,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.118391 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:47.254336 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.136s	user 0.106s	sys 0.027s 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":1150,"lbm_read_time_us":9892,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25374,"lbm_writes_lt_1ms":443,"mutex_wait_us":571,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:18:47.255167 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:47.297986 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.042s	user 0.014s	sys 0.028s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":19172,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.298470 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.310660 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4663,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.311132 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:47.452980 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.142s	user 0.110s	sys 0.031s 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":869,"lbm_read_time_us":10534,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28135,"lbm_writes_lt_1ms":443,"mutex_wait_us":112,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:18:47.453810 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:47.502168 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.048s	user 0.023s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.502661 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.513700 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.514308 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:47.654172 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.140s	user 0.107s	sys 0.032s 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":151,"lbm_read_time_us":9689,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29315,"lbm_writes_lt_1ms":443,"mutex_wait_us":35,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:47.654892 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:47.705472 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.050s	user 0.023s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15991,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:47.706095 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.717185 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.717658 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:47.764758 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.047s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1584,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:47.765602 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): free 124257291 bytes of WAL
I20260812 06:18:47.765851 19185 log_reader.cc:385] T fece2f8ed12d4ac0b56af146f44fdbd5: removed 12 log segments from log reader
I20260812 06:18:47.765913 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000003 (ops 12-16)
I20260812 06:18:47.766016 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000004 (ops 17-21)
I20260812 06:18:47.766073 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000005 (ops 22-26)
I20260812 06:18:47.766120 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000006 (ops 27-31)
I20260812 06:18:47.766165 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000007 (ops 32-36)
I20260812 06:18:47.766207 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000008 (ops 37-41)
I20260812 06:18:47.766250 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000009 (ops 42-46)
I20260812 06:18:47.766320 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000010 (ops 47-51)
I20260812 06:18:47.766386 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000011 (ops 52-56)
I20260812 06:18:47.766434 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000012 (ops 57-61)
I20260812 06:18:47.766484 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000013 (ops 62-66)
I20260812 06:18:47.766526 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000014 (ops 67-70)
I20260812 06:18:47.796851 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.031s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:47.797429 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.818454 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.021s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5799,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.818969 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:47.829758 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:47.830188 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:48.062561 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.232s	user 0.134s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877339,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":666,"lbm_read_time_us":16333,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37098,"lbm_writes_lt_1ms":643,"mutex_wait_us":58,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9088,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:18:48.063340 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): 482 bytes on disk
I20260812 06:18:48.063868 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":98,"lbm_reads_lt_1ms":4}
I20260812 06:18:48.064535 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=17.071750
I20260812 06:18:48.121724 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.057s	user 0.045s	sys 0.011s Metrics: {"bytes_written":18953399,"delete_count":0,"lbm_write_time_us":26571,"lbm_writes_lt_1ms":465,"reinsert_count":0,"update_count":2310}
I20260812 06:18:48.122285 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:48.132766 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.010s	user 0.001s	sys 0.005s Metrics: {"bytes_written":1969357,"delete_count":0,"lbm_write_time_us":2615,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:18:48.133306 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:48.143179 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.010s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3917,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:48.143606 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:48.361349 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.218s	user 0.116s	sys 0.096s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877162,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":260,"lbm_read_time_us":15350,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35043,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":31488,"update_count":3000}
I20260812 06:18:48.362069 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=18.063937
I20260812 06:18:48.435174 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.073s	user 0.034s	sys 0.020s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25975,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.435812 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:48.447676 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.448172 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:48.665478 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.217s	user 0.125s	sys 0.087s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":824,"lbm_read_time_us":16484,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35522,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":3000}
I20260812 06:18:48.666234 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=18.063937
I20260812 06:18:48.728024 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.062s	user 0.033s	sys 0.024s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27664,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:48.728570 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:48.740872 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4377,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:48.741531 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:48.944696 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.203s	user 0.122s	sys 0.079s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":14676,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33080,"lbm_writes_lt_1ms":643,"mutex_wait_us":28,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16000,"update_count":3000}
I20260812 06:18:48.945468 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=16.079562
I20260812 06:18:49.008096 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.062s	user 0.031s	sys 0.023s Metrics: {"bytes_written":18255989,"delete_count":0,"lbm_write_time_us":25878,"lbm_writes_lt_1ms":448,"reinsert_count":0,"update_count":2225}
I20260812 06:18:49.008623 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=5.165500
I20260812 06:18:49.026849 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":6359000,"delete_count":0,"lbm_write_time_us":7876,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:18:49.027374 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:49.244936 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.217s	user 0.137s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877111,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":358,"lbm_read_time_us":14803,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34972,"lbm_writes_lt_1ms":643,"mutex_wait_us":63,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3000}
I20260812 06:18:49.245656 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=17.071750
I20260812 06:18:49.315092 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.069s	user 0.037s	sys 0.019s Metrics: {"bytes_written":18994429,"delete_count":0,"lbm_write_time_us":26140,"lbm_writes_lt_1ms":466,"reinsert_count":0,"update_count":2315}
I20260812 06:18:49.315636 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=4.173312
I20260812 06:18:49.332901 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.017s	user 0.011s	sys 0.003s Metrics: {"bytes_written":5620564,"delete_count":0,"lbm_write_time_us":6946,"lbm_writes_lt_1ms":140,"reinsert_count":0,"update_count":685}
I20260812 06:18:49.333488 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:49.362591 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.029s	user 0.022s	sys 0.005s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1119,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1820,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:18:49.363188 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): free 133024406 bytes of WAL
I20260812 06:18:49.363408 19185 log_reader.cc:385] T fece2f8ed12d4ac0b56af146f44fdbd5: removed 13 log segments from log reader
I20260812 06:18:49.363456 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000015 (ops 71-75)
I20260812 06:18:49.363487 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000016 (ops 76-80)
I20260812 06:18:49.363549 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000017 (ops 81-85)
I20260812 06:18:49.363611 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000018 (ops 86-90)
I20260812 06:18:49.363651 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000019 (ops 91-94)
I20260812 06:18:49.363693 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000020 (ops 95-99)
I20260812 06:18:49.363732 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000021 (ops 100-104)
I20260812 06:18:49.363755 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000022 (ops 105-109)
I20260812 06:18:49.363795 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000023 (ops 110-114)
I20260812 06:18:49.363834 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000024 (ops 115-119)
I20260812 06:18:49.363873 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000025 (ops 120-124)
I20260812 06:18:49.363910 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000026 (ops 125-129)
I20260812 06:18:49.363946 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000027 (ops 130-134)
I20260812 06:18:49.395720 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.032s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:49.396289 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): 493 bytes on disk
I20260812 06:18:49.396827 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) 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:49.397447 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=6.157687
I20260812 06:18:49.419094 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.021s	user 0.015s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8982,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:49.419602 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:49.657590 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.238s	user 0.158s	sys 0.080s Metrics: {"cfile_cache_miss":833,"cfile_cache_miss_bytes":37082059,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":527,"lbm_read_time_us":19726,"lbm_reads_lt_1ms":869,"lbm_write_time_us":43586,"lbm_writes_lt_1ms":843,"mutex_wait_us":102,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":80,"threads_started":1,"update_count":4000}
I20260812 06:18:49.660470 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=18.063937
I20260812 06:18:49.720259 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.060s	user 0.045s	sys 0.011s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":26918,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:49.720717 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:49.745796 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.025s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5451,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.746238 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:49.756697 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4240,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:49.757244 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:49.951678 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.194s	user 0.145s	sys 0.049s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":138,"lbm_read_time_us":14736,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42446,"lbm_writes_lt_1ms":743,"mutex_wait_us":23,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3500}
I20260812 06:18:49.952596 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=14.095187
I20260812 06:18:50.006409 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24230,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.007184 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:50.022423 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5720,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.022894 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:50.201653 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.179s	user 0.137s	sys 0.024s 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":1009,"lbm_read_time_us":11488,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32547,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":21376,"update_count":2500}
I20260812 06:18:50.202275 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=14.095187
I20260812 06:18:50.261291 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.059s	user 0.035s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21337,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.261826 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:50.273844 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.012s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.274456 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:50.468575 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.194s	user 0.126s	sys 0.065s 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":691,"lbm_read_time_us":14074,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32543,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:18:50.469345 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=14.095187
I20260812 06:18:50.522701 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.053s	user 0.021s	sys 0.027s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23017,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.523178 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:50.669625 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.146s	user 0.091s	sys 0.053s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":260,"lbm_read_time_us":11718,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23790,"lbm_writes_lt_1ms":443,"mutex_wait_us":50,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35456,"update_count":2000}
I20260812 06:18:50.670379 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=14.095187
I20260812 06:18:50.724010 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.053s	user 0.037s	sys 0.008s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":21981,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:50.724553 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:50.736388 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4334,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:50.736876 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:50.773180 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushMRSOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.036s	user 0.035s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1225,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2211,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:50.773844 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): free 121006700 bytes of WAL
I20260812 06:18:50.774060 19185 log_reader.cc:385] T fece2f8ed12d4ac0b56af146f44fdbd5: removed 12 log segments from log reader
I20260812 06:18:50.774101 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000028 (ops 135-139)
I20260812 06:18:50.774128 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000029 (ops 140-144)
I20260812 06:18:50.774189 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000030 (ops 145-149)
I20260812 06:18:50.774237 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000031 (ops 150-154)
I20260812 06:18:50.774278 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000032 (ops 155-159)
I20260812 06:18:50.774349 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000033 (ops 160-164)
I20260812 06:18:50.774395 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000034 (ops 165-169)
I20260812 06:18:50.774435 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000035 (ops 170-174)
I20260812 06:18:50.774472 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000036 (ops 175-178)
I20260812 06:18:50.774536 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000037 (ops 179-183)
I20260812 06:18:50.774577 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000038 (ops 184-188)
I20260812 06:18:50.774616 19185 log.cc:1079] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: Deleting log segment in path: /tmp/dist-test-taskvtaN54/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515520197569-18694-0/minicluster-data/ts-0-root/wals/fece2f8ed12d4ac0b56af146f44fdbd5/wal-000000039 (ops 189-193)
I20260812 06:18:50.803328 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: LogGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:18:50.803704 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=3.181125
I20260812 06:18:50.827358 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.023s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":7338,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:50.827848 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5): 447 bytes on disk
I20260812 06:18:50.828262 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: UndoDeltaBlockGCOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:18:50.828855 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=2.188937
I20260812 06:18:50.838944 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3922,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:50.839449 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=1.000000
I20260812 06:18:50.969624 18694 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.946s	user 1.831s	sys 0.155s
I20260812 06:18:51.073684 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: MajorDeltaCompactionOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.233s	user 0.135s	sys 0.095s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979743,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2822,"dirs.run_cpu_time_us":469,"dirs.run_wall_time_us":2977,"lbm_read_time_us":19002,"lbm_reads_lt_1ms":770,"lbm_write_time_us":36805,"lbm_writes_lt_1ms":743,"mutex_wait_us":2149,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24192,"update_count":3500}
I20260812 06:18:51.074419 19282 maintenance_manager.cc:419] P 2dbecaaee34c4d7e94791dcd4a100ce2: Scheduling FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5): perf score=10.126437
I20260812 06:18:51.078110 18694 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.108s	user 0.002s	sys 0.000s
I20260812 06:18:51.078572 18694 tablet_server.cc:179] TabletServer@127.18.65.129:0 shutting down...
I20260812 06:18:51.109992 19185 maintenance_manager.cc:643] P 2dbecaaee34c4d7e94791dcd4a100ce2: FlushDeltaMemStoresOp(fece2f8ed12d4ac0b56af146f44fdbd5) complete. Timing: real 0.035s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16027,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:51.110819 18694 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:51.111025 18694 tablet_replica.cc:333] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2: stopping tablet replica
I20260812 06:18:51.111184 18694 raft_consensus.cc:2243] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.111361 18694 raft_consensus.cc:2272] T fece2f8ed12d4ac0b56af146f44fdbd5 P 2dbecaaee34c4d7e94791dcd4a100ce2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.124737 18694 tablet_server.cc:196] TabletServer@127.18.65.129:0 shutdown complete.
I20260812 06:18:51.128401 18694 master.cc:562] Master@127.18.65.190:45733 shutting down...
I20260812 06:18:51.131682 18694 raft_consensus.cc:2243] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:51.131837 18694 raft_consensus.cc:2272] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:51.131886 18694 tablet_replica.cc:333] T 00000000000000000000000000000000 P ca0fc47d4c9742da8630dcdd61274de5: stopping tablet replica
I20260812 06:18:51.144335 18694 master.cc:584] Master@127.18.65.190:45733 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5431 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11031 ms total)

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