[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:29.194604 10684 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.111.62:45001
I20260812 06:19:29.195722 10684 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:29.196398 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:29.203626 10691 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:29.203773 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:29.203630 10696 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:29.203946 10693 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:29.204597 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:29.204707 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:29.204736 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515569204735 us; error 0 us; skew 500 ppm
I20260812 06:19:29.206866 10684 webserver.cc:533] Webserver started at http://127.10.111.62:40479/ using document root <none> and password file <none>
I20260812 06:19:29.207451 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:29.207517 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:29.207724 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:29.209465 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/master-0-root/instance:
uuid: "23b61811eb8b4465b62e076853e885b8"
format_stamp: "Formatted at 2026-08-12 06:19:29 on dist-test-slave-g350"
I20260812 06:19:29.213881 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:19:29.216590 10703 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:29.217976 10684 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:29.218158 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/master-0-root
uuid: "23b61811eb8b4465b62e076853e885b8"
format_stamp: "Formatted at 2026-08-12 06:19:29 on dist-test-slave-g350"
I20260812 06:19:29.218302 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:29.235954 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:29.236728 10684 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:29.236953 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:29.246188 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.62:45001
I20260812 06:19:29.246201 10761 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.62:45001 every 8 connection(s)
I20260812 06:19:29.248772 10762 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:29.254848 10762 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: Bootstrap starting.
I20260812 06:19:29.257395 10762 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:29.258463 10762 log.cc:826] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:29.260454 10762 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: No bootstrap required, opened a new log
I20260812 06:19:29.263578 10762 raft_consensus.cc:359] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER }
I20260812 06:19:29.263795 10762 raft_consensus.cc:385] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:29.263846 10762 raft_consensus.cc:740] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 23b61811eb8b4465b62e076853e885b8, State: Initialized, Role: FOLLOWER
I20260812 06:19:29.264559 10762 consensus_queue.cc:260] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [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: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER }
I20260812 06:19:29.264727 10762 raft_consensus.cc:399] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:29.264844 10762 raft_consensus.cc:493] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:29.265022 10762 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:29.266393 10762 raft_consensus.cc:515] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER }
I20260812 06:19:29.266959 10762 leader_election.cc:304] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [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: 23b61811eb8b4465b62e076853e885b8; no voters: 
I20260812 06:19:29.267391 10762 leader_election.cc:290] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:29.267592 10766 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:29.267879 10766 raft_consensus.cc:697] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 1 LEADER]: Becoming Leader. State: Replica: 23b61811eb8b4465b62e076853e885b8, State: Running, Role: LEADER
I20260812 06:19:29.268523 10766 consensus_queue.cc:237] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [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: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER }
I20260812 06:19:29.268579 10762 sys_catalog.cc:565] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:29.270617 10768 sys_catalog.cc:455] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 23b61811eb8b4465b62e076853e885b8. Latest consensus state: current_term: 1 leader_uuid: "23b61811eb8b4465b62e076853e885b8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER } }
I20260812 06:19:29.270665 10767 sys_catalog.cc:455] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "23b61811eb8b4465b62e076853e885b8" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "23b61811eb8b4465b62e076853e885b8" member_type: VOTER } }
I20260812 06:19:29.270777 10768 sys_catalog.cc:458] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:29.270790 10767 sys_catalog.cc:458] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:29.271225 10776 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:29.274099 10776 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:29.274407 10684 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:29.279963 10776 catalog_manager.cc:1383] Generated new cluster ID: 8e54b72fe0f840dcb14d56c73e65f3f2
I20260812 06:19:29.280066 10776 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:29.295759 10776 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:29.297116 10776 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:29.309149 10776 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: Generated new TSK 0
I20260812 06:19:29.310079 10776 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:29.339643 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:29.342674 10787 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:29.342746 10786 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:29.342911 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:29.342711 10789 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:29.343334 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:29.343387 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:29.343405 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515569343404 us; error 0 us; skew 500 ppm
I20260812 06:19:29.344605 10684 webserver.cc:533] Webserver started at http://127.10.111.1:34167/ using document root <none> and password file <none>
I20260812 06:19:29.344827 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:29.344882 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:29.344990 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:29.345427 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/instance:
uuid: "945550da78b04daca852a7c319538f2e"
format_stamp: "Formatted at 2026-08-12 06:19:29 on dist-test-slave-g350"
I20260812 06:19:29.347122 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:29.348230 10796 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:29.348506 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:29.348587 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root
uuid: "945550da78b04daca852a7c319538f2e"
format_stamp: "Formatted at 2026-08-12 06:19:29 on dist-test-slave-g350"
I20260812 06:19:29.348693 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:29.362887 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:29.363451 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:29.364020 10684 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:29.365029 10684 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:29.365088 10684 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:29.365168 10684 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:29.365214 10684 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:29.372505 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.1:41315
I20260812 06:19:29.372568 10872 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.1:41315 every 8 connection(s)
I20260812 06:19:29.388940 10873 heartbeater.cc:344] Connected to a master server at 127.10.111.62:45001
I20260812 06:19:29.389281 10873 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:29.389863 10873 heartbeater.cc:507] Master 127.10.111.62:45001 requested a full tablet report, sending...
I20260812 06:19:29.391580 10722 ts_manager.cc:194] Registered new tserver with Master: 945550da78b04daca852a7c319538f2e (127.10.111.1:41315)
I20260812 06:19:29.391716 10684 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01850942s
I20260812 06:19:29.393092 10722 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:36886
I20260812 06:19:29.402761 10722 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:36902:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:29.420661 10832 tablet_service.cc:1511] Processing CreateTablet for tablet a92d1dd62358498a92a577f7dec1fb7b (DEFAULT_TABLE table=heavy-update-compaction-test [id=0651cdb21ca44a3ea9f2647a242443e9]), partition=
I20260812 06:19:29.421149 10832 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a92d1dd62358498a92a577f7dec1fb7b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:29.424001 10887 tablet_bootstrap.cc:492] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Bootstrap starting.
I20260812 06:19:29.424979 10887 tablet_bootstrap.cc:654] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:29.426641 10887 tablet_bootstrap.cc:492] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: No bootstrap required, opened a new log
I20260812 06:19:29.426749 10887 ts_tablet_manager.cc:1403] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:29.427299 10887 raft_consensus.cc:359] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "945550da78b04daca852a7c319538f2e" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 41315 } }
I20260812 06:19:29.427421 10887 raft_consensus.cc:385] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:29.427445 10887 raft_consensus.cc:740] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 945550da78b04daca852a7c319538f2e, State: Initialized, Role: FOLLOWER
I20260812 06:19:29.427610 10887 consensus_queue.cc:260] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [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: "945550da78b04daca852a7c319538f2e" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 41315 } }
I20260812 06:19:29.427716 10887 raft_consensus.cc:399] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:29.427809 10887 raft_consensus.cc:493] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:29.427901 10887 raft_consensus.cc:3060] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:29.428910 10887 raft_consensus.cc:515] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "945550da78b04daca852a7c319538f2e" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 41315 } }
I20260812 06:19:29.429090 10887 leader_election.cc:304] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [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: 945550da78b04daca852a7c319538f2e; no voters: 
I20260812 06:19:29.429347 10887 leader_election.cc:290] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:29.429456 10889 raft_consensus.cc:2804] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:29.429733 10889 raft_consensus.cc:697] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 1 LEADER]: Becoming Leader. State: Replica: 945550da78b04daca852a7c319538f2e, State: Running, Role: LEADER
I20260812 06:19:29.429800 10887 ts_tablet_manager.cc:1434] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:29.430011 10873 heartbeater.cc:499] Master 127.10.111.62:45001 was elected leader, sending a full tablet report...
I20260812 06:19:29.429970 10889 consensus_queue.cc:237] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [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: "945550da78b04daca852a7c319538f2e" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 41315 } }
I20260812 06:19:29.433360 10722 catalog_manager.cc:5719] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e reported cstate change: term changed from 0 to 1, leader changed from <none> to 945550da78b04daca852a7c319538f2e (127.10.111.1). New cstate: current_term: 1 leader_uuid: "945550da78b04daca852a7c319538f2e" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "945550da78b04daca852a7c319538f2e" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 41315 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:29.504143 10684 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.013s	sys 0.013s
I20260812 06:19:29.623911 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=15.086190
I20260812 06:19:29.811343 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.187s	user 0.140s	sys 0.043s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":286,"delete_count":0,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":783,"dirs.run_wall_time_us":1876,"drs_written":1,"lbm_read_time_us":87,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44479,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":191,"threads_started":1,"update_count":1500}
I20260812 06:19:29.812790 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling LogGCOp(a92d1dd62358498a92a577f7dec1fb7b): free 8725963 bytes of WAL
I20260812 06:19:29.813226 10802 log_reader.cc:385] T a92d1dd62358498a92a577f7dec1fb7b: removed 1 log segments from log reader
I20260812 06:19:29.813336 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000001 (ops 1-6)
I20260812 06:19:29.815878 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: LogGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:29.816383 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b): 12308959 bytes on disk
I20260812 06:19:29.817158 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":91,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.817716 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:29.835325 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6608,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.835994 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:29.985553 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.149s	user 0.109s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":503,"lbm_read_time_us":7722,"lbm_reads_lt_1ms":460,"lbm_write_time_us":30142,"lbm_writes_lt_1ms":443,"mutex_wait_us":117,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":363,"threads_started":5,"update_count":2000}
I20260812 06:19:29.986125 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:30.042673 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.056s	user 0.028s	sys 0.023s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":23890,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:30.043406 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:30.056839 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.013s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4463,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.057475 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:30.190181 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.132s	user 0.095s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1204,"lbm_read_time_us":8718,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27562,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16640,"update_count":2000}
I20260812 06:19:30.190898 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:30.233949 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.043s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15838,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.234551 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:30.247000 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.247658 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:30.381633 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.134s	user 0.115s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1282,"lbm_read_time_us":8058,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27754,"lbm_writes_lt_1ms":443,"mutex_wait_us":559,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18560,"update_count":2000}
I20260812 06:19:30.382345 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:30.438335 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.056s	user 0.035s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15303,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.438943 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:30.450722 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.451210 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:30.624598 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.173s	user 0.097s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":10358,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26139,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.625310 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:30.677405 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.052s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16849,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.678069 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:30.690207 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4285,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.690948 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:30.835608 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.144s	user 0.132s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":9875,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28622,"lbm_writes_lt_1ms":443,"mutex_wait_us":31,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:30.836372 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:30.873153 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.037s	user 0.013s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16107,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:30.873759 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:30.893537 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.020s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.894074 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:31.019330 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.125s	user 0.109s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":272,"lbm_read_time_us":9465,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23999,"lbm_writes_lt_1ms":443,"mutex_wait_us":36,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:31.020045 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:31.063971 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.044s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19777,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:31.064662 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:31.080513 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.081238 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:31.114351 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.033s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":116,"dirs.run_cpu_time_us":368,"dirs.run_wall_time_us":1710,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2243,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:31.115440 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling LogGCOp(a92d1dd62358498a92a577f7dec1fb7b): free 123804179 bytes of WAL
I20260812 06:19:31.115747 10802 log_reader.cc:385] T a92d1dd62358498a92a577f7dec1fb7b: removed 12 log segments from log reader
I20260812 06:19:31.115821 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000002 (ops 7-11)
I20260812 06:19:31.115911 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000003 (ops 12-16)
I20260812 06:19:31.115953 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000004 (ops 17-21)
I20260812 06:19:31.115990 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000005 (ops 22-26)
I20260812 06:19:31.116037 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000006 (ops 27-31)
I20260812 06:19:31.116067 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000007 (ops 32-36)
I20260812 06:19:31.116087 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000008 (ops 37-40)
I20260812 06:19:31.116134 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000009 (ops 41-45)
I20260812 06:19:31.116178 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000010 (ops 46-50)
I20260812 06:19:31.116204 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000011 (ops 51-55)
I20260812 06:19:31.116240 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000012 (ops 56-60)
I20260812 06:19:31.116277 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000013 (ops 61-64)
I20260812 06:19:31.143096 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: LogGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:31.143671 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b): 447 bytes on disk
I20260812 06:19:31.144143 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.144740 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=3.181125
I20260812 06:19:31.161872 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.017s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6948,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:31.162444 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:31.177423 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5440,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.178342 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:31.380592 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.202s	user 0.130s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":704,"lbm_read_time_us":12963,"lbm_reads_lt_1ms":674,"lbm_write_time_us":44688,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":642,"mutex_wait_us":93,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"thread_start_us":175,"threads_started":1,"update_count":3000}
I20260812 06:19:31.382673 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:31.443993 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.061s	user 0.043s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23466,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.444507 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:31.456836 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4304,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.458491 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:31.625836 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.167s	user 0.117s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1136,"lbm_read_time_us":12441,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35215,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2500}
I20260812 06:19:31.626464 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=11.118625
I20260812 06:19:31.659749 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.033s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14297,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.660768 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:31.680771 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6779,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.681440 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:31.846005 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.164s	user 0.113s	sys 0.050s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631305,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":540,"lbm_read_time_us":9906,"lbm_reads_lt_1ms":468,"lbm_write_time_us":30091,"lbm_writes_lt_1ms":443,"mutex_wait_us":1,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:31.846722 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:31.896664 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.047s	user 0.015s	sys 0.029s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16691,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:31.897440 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:31.915485 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5481,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:31.916014 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:32.093776 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.178s	user 0.124s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":506,"lbm_read_time_us":9526,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28524,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12032,"update_count":2000}
I20260812 06:19:32.094430 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:32.155247 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.061s	user 0.035s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.155818 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:32.168867 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.169890 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:32.327925 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.158s	user 0.125s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":12918,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32225,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6272,"update_count":2500}
I20260812 06:19:32.328591 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:32.370476 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.042s	user 0.029s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18127,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.371013 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:32.388744 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.018s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6761,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.389393 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:32.521853 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.132s	user 0.089s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":8877,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26315,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:32.522842 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:32.567817 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.045s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17760,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:32.568558 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:32.581707 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.013s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.582454 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:32.615422 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.033s	user 0.028s	sys 0.003s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":189,"dirs.run_wall_time_us":1304,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1867,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:32.616508 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling LogGCOp(a92d1dd62358498a92a577f7dec1fb7b): free 108988507 bytes of WAL
I20260812 06:19:32.616854 10802 log_reader.cc:385] T a92d1dd62358498a92a577f7dec1fb7b: removed 11 log segments from log reader
I20260812 06:19:32.616933 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000014 (ops 65-69)
I20260812 06:19:32.616989 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000015 (ops 70-74)
I20260812 06:19:32.617050 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000016 (ops 75-78)
I20260812 06:19:32.617090 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000017 (ops 79-83)
I20260812 06:19:32.617127 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000018 (ops 84-88)
I20260812 06:19:32.617164 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000019 (ops 89-93)
I20260812 06:19:32.617201 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000020 (ops 94-98)
I20260812 06:19:32.617242 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000021 (ops 99-103)
I20260812 06:19:32.617273 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000022 (ops 104-108)
I20260812 06:19:32.617316 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000023 (ops 109-113)
I20260812 06:19:32.617353 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000024 (ops 114-118)
I20260812 06:19:32.642647 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: LogGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:32.643122 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b): 447 bytes on disk
I20260812 06:19:32.643712 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.644475 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=3.181125
I20260812 06:19:32.658885 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.014s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4851,"lbm_writes_lt_1ms":113,"mutex_wait_us":136,"reinsert_count":0,"update_count":550}
I20260812 06:19:32.659390 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling LogGCOp(a92d1dd62358498a92a577f7dec1fb7b): free 11564875 bytes of WAL
I20260812 06:19:32.659610 10802 log_reader.cc:385] T a92d1dd62358498a92a577f7dec1fb7b: removed 1 log segments from log reader
I20260812 06:19:32.659653 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000025 (ops 119-122)
I20260812 06:19:32.661954 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: LogGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:32.662317 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:32.674641 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3807,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:32.675330 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:32.877944 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.202s	user 0.159s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3307,"lbm_read_time_us":11582,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39935,"lbm_writes_lt_1ms":643,"mutex_wait_us":2188,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13056,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:19:32.878707 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:32.932565 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.054s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409897,"delete_count":0,"lbm_write_time_us":22572,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.933123 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:32.946599 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.013s	user 0.003s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5069,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.947180 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:33.114380 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.167s	user 0.124s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733718,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2121,"lbm_read_time_us":11939,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32969,"lbm_writes_lt_1ms":543,"mutex_wait_us":527,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2500}
I20260812 06:19:33.115163 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=11.118625
I20260812 06:19:33.156323 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.041s	user 0.013s	sys 0.025s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16995,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.157018 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:33.183436 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.026s	user 0.010s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5666,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.184034 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:33.196362 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.196945 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:33.388820 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.192s	user 0.144s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733835,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":370,"lbm_read_time_us":12738,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32549,"lbm_writes_lt_1ms":543,"mutex_wait_us":26,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:33.389460 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:33.432140 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.042s	user 0.021s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.432873 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:33.592870 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.160s	user 0.113s	sys 0.045s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20631194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":189,"lbm_read_time_us":10266,"lbm_reads_lt_1ms":467,"lbm_write_time_us":27177,"lbm_writes_lt_1ms":443,"mutex_wait_us":26,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2000}
I20260812 06:19:33.593995 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=11.118625
I20260812 06:19:33.641785 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.048s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20355,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:33.642596 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:33.660315 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.018s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.661338 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:33.678032 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6317,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:33.678774 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:33.879992 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.201s	user 0.151s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733834,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":326,"lbm_read_time_us":12580,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30168,"lbm_writes_lt_1ms":543,"mutex_wait_us":114,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2500}
I20260812 06:19:33.880545 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:33.937242 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.057s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":22907,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:33.937870 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:33.953109 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6290,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.953794 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:34.122581 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.169s	user 0.123s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733727,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":11172,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33614,"lbm_writes_lt_1ms":543,"mutex_wait_us":285,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:34.123364 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=11.118625
I20260812 06:19:34.164176 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.041s	user 0.026s	sys 0.012s Metrics: {"bytes_written":12881836,"delete_count":0,"lbm_write_time_us":17634,"lbm_writes_lt_1ms":317,"reinsert_count":0,"update_count":1570}
I20260812 06:19:34.165096 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:34.186738 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.021s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":4237,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:34.187373 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:34.199810 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.012s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4742,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.200700 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:34.235344 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushMRSOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.034s	user 0.028s	sys 0.004s Metrics: {"bytes_written":1275446,"cfile_init":1,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":283,"dirs.run_wall_time_us":1559,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1926,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:34.236172 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling LogGCOp(a92d1dd62358498a92a577f7dec1fb7b): free 120553609 bytes of WAL
I20260812 06:19:34.236459 10802 log_reader.cc:385] T a92d1dd62358498a92a577f7dec1fb7b: removed 12 log segments from log reader
I20260812 06:19:34.236505 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000026 (ops 123-127)
I20260812 06:19:34.236536 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000027 (ops 128-132)
I20260812 06:19:34.236598 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000028 (ops 133-136)
I20260812 06:19:34.236646 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000029 (ops 137-141)
I20260812 06:19:34.236706 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000030 (ops 142-146)
I20260812 06:19:34.236735 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000031 (ops 147-151)
I20260812 06:19:34.236791 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000032 (ops 152-156)
I20260812 06:19:34.236838 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000033 (ops 157-160)
I20260812 06:19:34.236881 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000034 (ops 161-165)
I20260812 06:19:34.236920 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000035 (ops 166-170)
I20260812 06:19:34.236960 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000036 (ops 171-175)
I20260812 06:19:34.236999 10802 log.cc:1079] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/a92d1dd62358498a92a577f7dec1fb7b/wal-000000037 (ops 176-180)
I20260812 06:19:34.265398 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: LogGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:34.265903 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b): 480 bytes on disk
I20260812 06:19:34.266547 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: UndoDeltaBlockGCOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":86,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.267536 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=3.181125
I20260812 06:19:34.299594 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.032s	user 0.012s	sys 0.016s Metrics: {"bytes_written":4512901,"delete_count":0,"lbm_write_time_us":8454,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:34.300257 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:34.310847 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:34.311380 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:34.559687 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.248s	user 0.145s	sys 0.100s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32938885,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1535,"lbm_read_time_us":18121,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41460,"lbm_writes_lt_1ms":743,"mutex_wait_us":417,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":46592,"thread_start_us":152,"threads_started":1,"update_count":3500}
I20260812 06:19:34.560464 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=14.095187
I20260812 06:19:34.612818 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.052s	user 0.041s	sys 0.008s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23344,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:34.613734 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=2.188937
I20260812 06:19:34.631829 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.018s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6769,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.632439 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=1.000000
I20260812 06:19:34.763363 10684 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.259s	user 1.957s	sys 0.091s
I20260812 06:19:34.802408 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: MajorDeltaCompactionOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.170s	user 0.121s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733726,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"lbm_read_time_us":11109,"lbm_reads_lt_1ms":568,"lbm_write_time_us":31190,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:34.803117 10874 maintenance_manager.cc:419] P 945550da78b04daca852a7c319538f2e: Scheduling FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b): perf score=10.126437
I20260812 06:19:34.829849 10684 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.066s	user 0.003s	sys 0.000s
I20260812 06:19:34.830528 10684 tablet_server.cc:179] TabletServer@127.10.111.1:0 shutting down...
I20260812 06:19:34.839342 10802 maintenance_manager.cc:643] P 945550da78b04daca852a7c319538f2e: FlushDeltaMemStoresOp(a92d1dd62358498a92a577f7dec1fb7b) complete. Timing: real 0.036s	user 0.019s	sys 0.015s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15804,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:34.840458 10684 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:34.841003 10684 tablet_replica.cc:333] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e: stopping tablet replica
I20260812 06:19:34.841275 10684 raft_consensus.cc:2243] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:34.841570 10684 raft_consensus.cc:2272] T a92d1dd62358498a92a577f7dec1fb7b P 945550da78b04daca852a7c319538f2e [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:34.860337 10684 tablet_server.cc:196] TabletServer@127.10.111.1:0 shutdown complete.
I20260812 06:19:34.866021 10684 master.cc:562] Master@127.10.111.62:45001 shutting down...
I20260812 06:19:34.871801 10684 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:34.872010 10684 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:34.872121 10684 tablet_replica.cc:333] T 00000000000000000000000000000000 P 23b61811eb8b4465b62e076853e885b8: stopping tablet replica
I20260812 06:19:34.884929 10684 master.cc:584] Master@127.10.111.62:45001 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5784 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:34.989013 10684 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.10.111.62:38501
I20260812 06:19:34.989498 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.992595 10910 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:34.992619 10913 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:34.992657 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:34.992615 10911 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:34.993088 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.993131 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:34.993147 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515574993148 us; error 0 us; skew 500 ppm
I20260812 06:19:34.994102 10684 webserver.cc:533] Webserver started at http://127.10.111.62:34513/ using document root <none> and password file <none>
I20260812 06:19:34.994303 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.994382 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.994494 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.994948 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/master-0-root/instance:
uuid: "5f394fe11f8440d9a709dfa4e5156dbb"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-g350"
I20260812 06:19:34.996807 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:34.998008 10920 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.998291 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:34.998390 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/master-0-root
uuid: "5f394fe11f8440d9a709dfa4e5156dbb"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-g350"
I20260812 06:19:34.998492 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:35.008713 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:35.009241 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:35.014626 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.62:38501
I20260812 06:19:35.019860 10981 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.62:38501 every 8 connection(s)
I20260812 06:19:35.020085 10982 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:35.022150 10982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb: Bootstrap starting.
I20260812 06:19:35.023013 10982 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:35.024178 10982 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb: No bootstrap required, opened a new log
I20260812 06:19:35.024673 10982 raft_consensus.cc:359] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER }
I20260812 06:19:35.024811 10982 raft_consensus.cc:385] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:35.024861 10982 raft_consensus.cc:740] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 5f394fe11f8440d9a709dfa4e5156dbb, State: Initialized, Role: FOLLOWER
I20260812 06:19:35.025027 10982 consensus_queue.cc:260] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [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: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER }
I20260812 06:19:35.025126 10982 raft_consensus.cc:399] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:35.025168 10982 raft_consensus.cc:493] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:35.025220 10982 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:35.026111 10982 raft_consensus.cc:515] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER }
I20260812 06:19:35.026284 10982 leader_election.cc:304] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [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: 5f394fe11f8440d9a709dfa4e5156dbb; no voters: 
I20260812 06:19:35.026507 10982 leader_election.cc:290] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:35.026686 10985 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:35.026918 10985 raft_consensus.cc:697] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 1 LEADER]: Becoming Leader. State: Replica: 5f394fe11f8440d9a709dfa4e5156dbb, State: Running, Role: LEADER
I20260812 06:19:35.027036 10982 sys_catalog.cc:565] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:35.027118 10985 consensus_queue.cc:237] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [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: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER }
I20260812 06:19:35.027612 10986 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER } }
I20260812 06:19:35.027733 10986 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:35.028072 10992 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:35.028241 10987 sys_catalog.cc:455] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [sys.catalog]: SysCatalogTable state changed. Reason: New leader 5f394fe11f8440d9a709dfa4e5156dbb. Latest consensus state: current_term: 1 leader_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "5f394fe11f8440d9a709dfa4e5156dbb" member_type: VOTER } }
I20260812 06:19:35.028330 10987 sys_catalog.cc:458] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:35.029112 10992 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:35.029441 10684 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:35.031145 10992 catalog_manager.cc:1383] Generated new cluster ID: bbc86498072f42d9b0dd0bdb1db0b8cf
I20260812 06:19:35.031224 10992 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:35.040066 10992 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:35.040735 10992 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:35.048907 10992 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb: Generated new TSK 0
I20260812 06:19:35.049302 10992 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:35.062394 10684 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:35.064824 11007 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:35.064906 10684 server_base.cc:1061] running on GCE node
W20260812 06:19:35.064931 11011 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:35.064900 11009 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:35.065412 10684 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:35.065466 10684 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:35.065483 10684 hybrid_clock.cc:648] HybridClock initialized: now 1786515575065483 us; error 0 us; skew 500 ppm
I20260812 06:19:35.066619 10684 webserver.cc:533] Webserver started at http://127.10.111.1:45237/ using document root <none> and password file <none>
I20260812 06:19:35.066777 10684 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:35.066823 10684 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:35.066888 10684 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:35.067260 10684 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/instance:
uuid: "b60cbe29436740e1a3ca7f94896854f3"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-g350"
I20260812 06:19:35.068857 10684 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:35.070020 11016 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.070389 10684 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:35.070470 10684 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root
uuid: "b60cbe29436740e1a3ca7f94896854f3"
format_stamp: "Formatted at 2026-08-12 06:19:35 on dist-test-slave-g350"
I20260812 06:19:35.070569 10684 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:35.081254 10684 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:35.081919 10684 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:35.082350 10684 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:35.082960 10684 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:35.083038 10684 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.083122 10684 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:35.083176 10684 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:35.088734 10684 rpc_server.cc:307] RPC server started. Bound to: 127.10.111.1:38969
I20260812 06:19:35.091498 11092 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.10.111.1:38969 every 8 connection(s)
I20260812 06:19:35.101820 11093 heartbeater.cc:344] Connected to a master server at 127.10.111.62:38501
I20260812 06:19:35.101969 11093 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:35.102223 11093 heartbeater.cc:507] Master 127.10.111.62:38501 requested a full tablet report, sending...
I20260812 06:19:35.102988 10938 ts_manager.cc:194] Registered new tserver with Master: b60cbe29436740e1a3ca7f94896854f3 (127.10.111.1:38969)
I20260812 06:19:35.103678 10684 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013585604s
I20260812 06:19:35.103741 10938 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35674
I20260812 06:19:35.112908 10938 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35690:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:35.123095 11052 tablet_service.cc:1511] Processing CreateTablet for tablet 87566e0295bb40a6b44171b27bdf527d (DEFAULT_TABLE table=heavy-update-compaction-test [id=04c13c9b4eb24084963f199670ac8cd4]), partition=
I20260812 06:19:35.123392 11052 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 87566e0295bb40a6b44171b27bdf527d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:35.125587 11106 tablet_bootstrap.cc:492] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Bootstrap starting.
I20260812 06:19:35.126638 11106 tablet_bootstrap.cc:654] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:35.127907 11106 tablet_bootstrap.cc:492] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: No bootstrap required, opened a new log
I20260812 06:19:35.128028 11106 ts_tablet_manager.cc:1403] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:35.128624 11106 raft_consensus.cc:359] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b60cbe29436740e1a3ca7f94896854f3" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 38969 } }
I20260812 06:19:35.128760 11106 raft_consensus.cc:385] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:35.128809 11106 raft_consensus.cc:740] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b60cbe29436740e1a3ca7f94896854f3, State: Initialized, Role: FOLLOWER
I20260812 06:19:35.128971 11106 consensus_queue.cc:260] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [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: "b60cbe29436740e1a3ca7f94896854f3" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 38969 } }
I20260812 06:19:35.129094 11106 raft_consensus.cc:399] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:35.129142 11106 raft_consensus.cc:493] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:35.129199 11106 raft_consensus.cc:3060] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:35.130159 11106 raft_consensus.cc:515] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b60cbe29436740e1a3ca7f94896854f3" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 38969 } }
I20260812 06:19:35.130345 11106 leader_election.cc:304] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [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: b60cbe29436740e1a3ca7f94896854f3; no voters: 
I20260812 06:19:35.130601 11106 leader_election.cc:290] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:35.130828 11109 raft_consensus.cc:2804] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:35.131079 11106 ts_tablet_manager.cc:1434] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:35.131103 11093 heartbeater.cc:499] Master 127.10.111.62:38501 was elected leader, sending a full tablet report...
I20260812 06:19:35.131103 11109 raft_consensus.cc:697] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 1 LEADER]: Becoming Leader. State: Replica: b60cbe29436740e1a3ca7f94896854f3, State: Running, Role: LEADER
I20260812 06:19:35.131493 11109 consensus_queue.cc:237] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [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: "b60cbe29436740e1a3ca7f94896854f3" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 38969 } }
I20260812 06:19:35.133086 10938 catalog_manager.cc:5719] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 reported cstate change: term changed from 0 to 1, leader changed from <none> to b60cbe29436740e1a3ca7f94896854f3 (127.10.111.1). New cstate: current_term: 1 leader_uuid: "b60cbe29436740e1a3ca7f94896854f3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b60cbe29436740e1a3ca7f94896854f3" member_type: VOTER last_known_addr { host: "127.10.111.1" port: 38969 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:35.200114 10684 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.060s	user 0.021s	sys 0.004s
I20260812 06:19:35.342077 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushMRSOp(87566e0295bb40a6b44171b27bdf527d): perf score=15.086190
I20260812 06:19:35.523084 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushMRSOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.181s	user 0.134s	sys 0.044s Metrics: {"bytes_written":12799785,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1127,"drs_written":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44165,"lbm_writes_lt_1ms":679,"mutex_wait_us":1118,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":4864,"update_count":1560}
I20260812 06:19:35.523754 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling LogGCOp(87566e0295bb40a6b44171b27bdf527d): free 20743880 bytes of WAL
I20260812 06:19:35.523995 11021 log_reader.cc:385] T 87566e0295bb40a6b44171b27bdf527d: removed 2 log segments from log reader
I20260812 06:19:35.524061 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000001 (ops 1-6)
I20260812 06:19:35.524140 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000002 (ops 7-11)
I20260812 06:19:35.528704 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: LogGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.005s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:35.529142 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:35.558856 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.029s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3610359,"delete_count":0,"lbm_write_time_us":5406,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:35.559361 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:35.569792 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.010s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3960,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:35.570549 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:35.775440 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.205s	user 0.107s	sys 0.088s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24364549,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1165,"lbm_read_time_us":12546,"lbm_reads_lt_1ms":563,"lbm_write_time_us":31536,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":573,"threads_started":5,"update_count":2450}
I20260812 06:19:35.776443 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:35.852304 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.075s	user 0.035s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25585,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:35.853161 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d): 12719221 bytes on disk
I20260812 06:19:35.853827 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:35.854270 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:35.866035 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4111,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.866895 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:36.067413 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.200s	user 0.141s	sys 0.059s 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":180,"lbm_read_time_us":14258,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35724,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:36.068131 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:36.127370 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.059s	user 0.044s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":25262,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.128110 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:36.145268 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.017s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6829,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.145807 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:36.333165 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.187s	user 0.118s	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":1279,"lbm_read_time_us":12811,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32754,"lbm_writes_lt_1ms":543,"mutex_wait_us":336,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:36.333905 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:36.397030 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.063s	user 0.028s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23464,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.397758 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:36.428506 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.031s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.429024 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:36.441224 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.441879 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:36.674279 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.232s	user 0.141s	sys 0.089s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":250,"lbm_read_time_us":15513,"lbm_reads_lt_1ms":673,"lbm_write_time_us":38114,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":3000}
I20260812 06:19:36.675160 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=15.087375
I20260812 06:19:36.730432 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":24805,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:36.731076 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:36.750892 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6927,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.751646 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:36.763180 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4087,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.764078 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:36.995795 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.231s	user 0.155s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":996,"lbm_read_time_us":16771,"lbm_reads_lt_1ms":673,"lbm_write_time_us":39542,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:19:36.996978 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:37.061694 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.064s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25511,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.062348 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:37.074265 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4521,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.074870 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushMRSOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:37.110535 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushMRSOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.035s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":88,"dirs.run_cpu_time_us":232,"dirs.run_wall_time_us":1457,"drs_written":1,"lbm_read_time_us":106,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2313,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:37.111171 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling LogGCOp(87566e0295bb40a6b44171b27bdf527d): free 120553333 bytes of WAL
I20260812 06:19:37.111413 11021 log_reader.cc:385] T 87566e0295bb40a6b44171b27bdf527d: removed 12 log segments from log reader
I20260812 06:19:37.111456 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000003 (ops 12-16)
I20260812 06:19:37.111485 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000004 (ops 17-21)
I20260812 06:19:37.111532 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000005 (ops 22-26)
I20260812 06:19:37.111577 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000006 (ops 27-31)
I20260812 06:19:37.111629 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000007 (ops 32-36)
I20260812 06:19:37.111666 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000008 (ops 37-41)
I20260812 06:19:37.111755 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000009 (ops 42-46)
I20260812 06:19:37.111794 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000010 (ops 47-50)
I20260812 06:19:37.111841 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000011 (ops 51-55)
I20260812 06:19:37.111879 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000012 (ops 56-60)
I20260812 06:19:37.111917 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000013 (ops 61-64)
I20260812 06:19:37.111958 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000014 (ops 65-69)
I20260812 06:19:37.138411 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: LogGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:37.139135 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d): 482 bytes on disk
I20260812 06:19:37.139865 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.140447 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=3.181125
I20260812 06:19:37.163075 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.022s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7218,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:37.163590 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:37.173784 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.174314 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:37.415167 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.241s	user 0.145s	sys 0.088s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":723,"lbm_read_time_us":15506,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41815,"lbm_writes_lt_1ms":743,"mutex_wait_us":61,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17664,"thread_start_us":87,"threads_started":1,"update_count":3500}
I20260812 06:19:37.415962 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=18.063937
I20260812 06:19:37.486196 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.070s	user 0.042s	sys 0.027s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":31008,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:37.487118 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:37.515269 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.028s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.515897 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:37.527539 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4569,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.528095 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:37.725148 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.197s	user 0.148s	sys 0.048s 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":180,"lbm_read_time_us":15304,"lbm_reads_lt_1ms":773,"lbm_write_time_us":42838,"lbm_writes_lt_1ms":743,"mutex_wait_us":79,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":3500}
I20260812 06:19:37.725932 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:37.785979 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.060s	user 0.033s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23598,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.786674 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=3.181125
I20260812 06:19:37.799046 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4855,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:37.799575 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:37.810122 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.810637 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:37.987962 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.177s	user 0.139s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":338,"lbm_read_time_us":13360,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35070,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":24704,"update_count":3000}
I20260812 06:19:37.988852 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:38.046001 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.057s	user 0.029s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27078,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.046556 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.057513 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4278,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.058367 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:38.244139 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.185s	user 0.126s	sys 0.056s 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":327,"lbm_read_time_us":13267,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33932,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":32896,"update_count":2500}
I20260812 06:19:38.245179 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=12.110812
I20260812 06:19:38.297341 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.052s	user 0.027s	sys 0.021s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":22391,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":331,"reinsert_count":0,"update_count":1650}
I20260812 06:19:38.298120 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.315774 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.017s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3739,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:38.316293 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.327359 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.327929 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:38.524931 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.197s	user 0.126s	sys 0.065s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774772,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1185,"lbm_read_time_us":12317,"lbm_reads_lt_1ms":573,"lbm_write_time_us":35880,"lbm_writes_lt_1ms":543,"mutex_wait_us":615,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:19:38.525828 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=11.118625
I20260812 06:19:38.585671 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.060s	user 0.036s	sys 0.024s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":22928,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:38.586176 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.604223 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.018s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4184,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.604749 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.617264 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4891,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.617980 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushMRSOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:38.653059 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushMRSOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":2047,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1675,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:38.653868 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling LogGCOp(87566e0295bb40a6b44171b27bdf527d): free 124710309 bytes of WAL
I20260812 06:19:38.654163 11021 log_reader.cc:385] T 87566e0295bb40a6b44171b27bdf527d: removed 12 log segments from log reader
I20260812 06:19:38.654212 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000015 (ops 70-74)
I20260812 06:19:38.654243 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000016 (ops 75-79)
I20260812 06:19:38.654289 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000017 (ops 80-84)
I20260812 06:19:38.654336 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000018 (ops 85-89)
I20260812 06:19:38.654381 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000019 (ops 90-94)
I20260812 06:19:38.654426 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000020 (ops 95-99)
I20260812 06:19:38.654471 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000021 (ops 100-104)
I20260812 06:19:38.654515 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000022 (ops 105-109)
I20260812 06:19:38.654539 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000023 (ops 110-114)
I20260812 06:19:38.654567 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000024 (ops 115-119)
I20260812 06:19:38.654587 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000025 (ops 120-124)
I20260812 06:19:38.654603 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000026 (ops 125-129)
I20260812 06:19:38.681680 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: LogGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.028s	user 0.004s	sys 0.024s Metrics: {}
I20260812 06:19:38.682572 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d): 473 bytes on disk
I20260812 06:19:38.683188 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:19:38.683949 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=3.181125
I20260812 06:19:38.706496 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.022s	user 0.011s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7710,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:38.707001 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling LogGCOp(87566e0295bb40a6b44171b27bdf527d): free 12018006 bytes of WAL
I20260812 06:19:38.707216 11021 log_reader.cc:385] T 87566e0295bb40a6b44171b27bdf527d: removed 1 log segments from log reader
I20260812 06:19:38.707261 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000027 (ops 130-134)
I20260812 06:19:38.709692 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: LogGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:38.710072 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:38.721035 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3770,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.721580 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:38.953904 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.232s	user 0.173s	sys 0.053s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979849,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1594,"lbm_read_time_us":16052,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40882,"lbm_writes_lt_1ms":743,"mutex_wait_us":1654,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":21248,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:38.954764 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=18.063937
I20260812 06:19:39.017154 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.062s	user 0.029s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28147,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:39.017781 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:39.031332 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5286,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.032088 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:39.217289 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.185s	user 0.143s	sys 0.041s 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":2305,"lbm_read_time_us":13624,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36033,"lbm_writes_lt_1ms":643,"mutex_wait_us":44,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":42240,"update_count":3000}
I20260812 06:19:39.218150 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:39.282128 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.064s	user 0.031s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":29024,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.282639 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:39.308152 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.025s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6067,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.308648 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:39.319399 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4076,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.320005 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:39.497815 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.178s	user 0.119s	sys 0.054s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":405,"lbm_read_time_us":12469,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36914,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17152,"update_count":3000}
I20260812 06:19:39.498445 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:39.546046 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.047s	user 0.014s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20926,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.546741 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:39.570809 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.024s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7191,"lbm_writes_lt_1ms":103,"mutex_wait_us":1,"reinsert_count":0,"update_count":500}
I20260812 06:19:39.571406 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:39.738657 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.167s	user 0.132s	sys 0.027s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1306,"lbm_read_time_us":8616,"lbm_reads_lt_1ms":564,"lbm_write_time_us":32491,"lbm_writes_lt_1ms":543,"mutex_wait_us":450,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30720,"update_count":2500}
I20260812 06:19:39.739665 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=14.095187
I20260812 06:19:39.800992 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.061s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26704,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.801642 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:39.979985 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.178s	user 0.113s	sys 0.063s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1442,"lbm_read_time_us":12399,"lbm_reads_lt_1ms":463,"lbm_write_time_us":30285,"lbm_writes_lt_1ms":443,"mutex_wait_us":495,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:39.981171 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=11.118625
I20260812 06:19:40.026440 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.045s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12717738,"delete_count":0,"lbm_write_time_us":19410,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:40.027088 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:40.049311 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.022s	user 0.010s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":8046,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:40.049932 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushMRSOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:40.096026 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushMRSOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.046s	user 0.022s	sys 0.010s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":130,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1822,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2408,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:40.097308 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d): 447 bytes on disk
I20260812 06:19:40.098009 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: UndoDeltaBlockGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":81,"lbm_reads_lt_1ms":4}
I20260812 06:19:40.098626 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=3.181125
I20260812 06:19:40.119148 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.020s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5272,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:40.119820 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling LogGCOp(87566e0295bb40a6b44171b27bdf527d): free 108535632 bytes of WAL
I20260812 06:19:40.120179 11021 log_reader.cc:385] T 87566e0295bb40a6b44171b27bdf527d: removed 11 log segments from log reader
I20260812 06:19:40.120251 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000028 (ops 135-139)
I20260812 06:19:40.120421 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000029 (ops 140-144)
I20260812 06:19:40.120507 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000030 (ops 145-149)
I20260812 06:19:40.120584 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000031 (ops 150-154)
I20260812 06:19:40.120625 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000032 (ops 155-159)
I20260812 06:19:40.120648 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000033 (ops 160-164)
I20260812 06:19:40.120680 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000034 (ops 165-168)
I20260812 06:19:40.120714 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000035 (ops 169-173)
I20260812 06:19:40.120747 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000036 (ops 174-178)
I20260812 06:19:40.120777 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000037 (ops 179-182)
I20260812 06:19:40.120805 11021 log.cc:1079] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: Deleting log segment in path: /tmp/dist-test-taskZIIoqK/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515569183196-10684-0/minicluster-data/ts-0-root/wals/87566e0295bb40a6b44171b27bdf527d/wal-000000038 (ops 183-187)
I20260812 06:19:40.150359 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: LogGCOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:40.150836 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:40.178267 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.027s	user 0.005s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4791,"lbm_writes_lt_1ms":93,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":450}
I20260812 06:19:40.178763 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=2.188937
I20260812 06:19:40.189790 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4134,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.190320 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d): perf score=1.000000
I20260812 06:19:40.439657 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: MajorDeltaCompactionOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.249s	user 0.154s	sys 0.088s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":932,"lbm_read_time_us":15677,"lbm_reads_lt_1ms":775,"lbm_write_time_us":41670,"lbm_writes_lt_1ms":743,"mutex_wait_us":299,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":112,"threads_started":1,"update_count":3500}
I20260812 06:19:40.440299 11094 maintenance_manager.cc:419] P b60cbe29436740e1a3ca7f94896854f3: Scheduling FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d): perf score=16.079562
I20260812 06:19:40.450801 10684 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.251s	user 1.951s	sys 0.136s
I20260812 06:19:40.492887 10684 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.042s	user 0.001s	sys 0.000s
I20260812 06:19:40.493433 10684 tablet_server.cc:179] TabletServer@127.10.111.1:0 shutting down...
I20260812 06:19:40.502208 11021 maintenance_manager.cc:643] P b60cbe29436740e1a3ca7f94896854f3: FlushDeltaMemStoresOp(87566e0295bb40a6b44171b27bdf527d) complete. Timing: real 0.062s	user 0.037s	sys 0.023s Metrics: {"bytes_written":18543159,"delete_count":0,"lbm_write_time_us":27772,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":454,"reinsert_count":0,"update_count":2260}
I20260812 06:19:40.502903 10684 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:40.503124 10684 tablet_replica.cc:333] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3: stopping tablet replica
I20260812 06:19:40.503254 10684 raft_consensus.cc:2243] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:40.503474 10684 raft_consensus.cc:2272] T 87566e0295bb40a6b44171b27bdf527d P b60cbe29436740e1a3ca7f94896854f3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:40.508728 10684 tablet_server.cc:196] TabletServer@127.10.111.1:0 shutdown complete.
I20260812 06:19:40.512344 10684 master.cc:562] Master@127.10.111.62:38501 shutting down...
I20260812 06:19:40.516744 10684 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:40.516973 10684 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:40.517057 10684 tablet_replica.cc:333] T 00000000000000000000000000000000 P 5f394fe11f8440d9a709dfa4e5156dbb: stopping tablet replica
I20260812 06:19:40.529953 10684 master.cc:584] Master@127.10.111.62:38501 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5640 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11426 ms total)

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