[==========] 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:56.930307 16400 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.4.62:41921
I20260812 06:19:56.931536 16400 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:56.932243 16400 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.939116 16409 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:56.939146 16412 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.939206 16400 server_base.cc:1061] running on GCE node
W20260812 06:19:56.939435 16408 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:56.939916 16400 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.940024 16400 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:56.940066 16400 hybrid_clock.cc:648] HybridClock initialized: now 1786515596940064 us; error 0 us; skew 500 ppm
I20260812 06:19:56.941943 16400 webserver.cc:533] Webserver started at http://127.16.4.62:39433/ using document root <none> and password file <none>
I20260812 06:19:56.942502 16400 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.942569 16400 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.942806 16400 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.944456 16400 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/master-0-root/instance:
uuid: "7e538cb409cf49ad85f1066f95307507"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-lkx2"
I20260812 06:19:56.947801 16400 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:56.949810 16423 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.950850 16400 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:56.950959 16400 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/master-0-root
uuid: "7e538cb409cf49ad85f1066f95307507"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-lkx2"
I20260812 06:19:56.951049 16400 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:56.965040 16400 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.965696 16400 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:56.965864 16400 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.973140 16400 rpc_server.cc:307] RPC server started. Bound to: 127.16.4.62:41921
I20260812 06:19:56.973145 16506 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.4.62:41921 every 8 connection(s)
I20260812 06:19:56.975370 16508 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:56.980737 16508 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: Bootstrap starting.
I20260812 06:19:56.983047 16508 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.983917 16508 log.cc:826] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:56.985574 16508 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: No bootstrap required, opened a new log
I20260812 06:19:56.988231 16508 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER }
I20260812 06:19:56.988427 16508 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.988502 16508 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7e538cb409cf49ad85f1066f95307507, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.989076 16508 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [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: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER }
I20260812 06:19:56.989229 16508 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.989296 16508 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.989418 16508 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.990145 16508 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER }
I20260812 06:19:56.990568 16508 leader_election.cc:304] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [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: 7e538cb409cf49ad85f1066f95307507; no voters: 
I20260812 06:19:56.990878 16508 leader_election.cc:290] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.991010 16513 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.991240 16513 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 1 LEADER]: Becoming Leader. State: Replica: 7e538cb409cf49ad85f1066f95307507, State: Running, Role: LEADER
I20260812 06:19:56.991587 16513 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [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: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER }
I20260812 06:19:56.991806 16508 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:56.993382 16514 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7e538cb409cf49ad85f1066f95307507" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER } }
I20260812 06:19:56.993521 16514 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.993804 16515 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7e538cb409cf49ad85f1066f95307507. Latest consensus state: current_term: 1 leader_uuid: "7e538cb409cf49ad85f1066f95307507" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7e538cb409cf49ad85f1066f95307507" member_type: VOTER } }
I20260812 06:19:56.993886 16515 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.994009 16400 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:56.993887 16530 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:56.996095 16530 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:57.000669 16530 catalog_manager.cc:1383] Generated new cluster ID: 92b62782cbd1479d8bbde98ee7ca1e09
I20260812 06:19:57.000731 16530 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:57.018569 16530 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:57.019804 16530 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:57.029542 16530 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: Generated new TSK 0
I20260812 06:19:57.030344 16530 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:57.058912 16400 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:57.061887 16545 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:57.061765 16542 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:57.061765 16541 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:57.062143 16400 server_base.cc:1061] running on GCE node
I20260812 06:19:57.062310 16400 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:57.062350 16400 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:57.062369 16400 hybrid_clock.cc:648] HybridClock initialized: now 1786515597062369 us; error 0 us; skew 500 ppm
I20260812 06:19:57.063215 16400 webserver.cc:533] Webserver started at http://127.16.4.1:42037/ using document root <none> and password file <none>
I20260812 06:19:57.063395 16400 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:57.063445 16400 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:57.063524 16400 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:57.063900 16400 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/instance:
uuid: "4e4d43c04cb74c708c53f76ece965603"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-lkx2"
I20260812 06:19:57.065418 16400 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:57.066351 16551 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:57.066596 16400 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:57.066658 16400 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root
uuid: "4e4d43c04cb74c708c53f76ece965603"
format_stamp: "Formatted at 2026-08-12 06:19:57 on dist-test-slave-lkx2"
I20260812 06:19:57.066730 16400 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-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:57.073999 16400 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:57.074412 16400 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:57.074878 16400 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:57.075747 16400 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:57.075799 16400 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.075850 16400 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:57.075879 16400 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:57.082455 16400 rpc_server.cc:307] RPC server started. Bound to: 127.16.4.1:46019
I20260812 06:19:57.082511 16647 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.4.1:46019 every 8 connection(s)
I20260812 06:19:57.097091 16648 heartbeater.cc:344] Connected to a master server at 127.16.4.62:41921
I20260812 06:19:57.097353 16648 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:57.097898 16648 heartbeater.cc:507] Master 127.16.4.62:41921 requested a full tablet report, sending...
I20260812 06:19:57.099404 16453 ts_manager.cc:194] Registered new tserver with Master: 4e4d43c04cb74c708c53f76ece965603 (127.16.4.1:46019)
I20260812 06:19:57.100013 16400 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016911013s
I20260812 06:19:57.100767 16453 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54220
I20260812 06:19:57.110110 16453 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54222:
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:57.125325 16589 tablet_service.cc:1511] Processing CreateTablet for tablet 2dc4c13b05d2482cb6e729211100507c (DEFAULT_TABLE table=heavy-update-compaction-test [id=1c3eaf17a2364821bc027c3e136458c8]), partition=
I20260812 06:19:57.125840 16589 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2dc4c13b05d2482cb6e729211100507c. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:57.128216 16672 tablet_bootstrap.cc:492] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Bootstrap starting.
I20260812 06:19:57.129632 16672 tablet_bootstrap.cc:654] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:57.130982 16672 tablet_bootstrap.cc:492] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: No bootstrap required, opened a new log
I20260812 06:19:57.131096 16672 ts_tablet_manager.cc:1403] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:57.132071 16672 raft_consensus.cc:359] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e4d43c04cb74c708c53f76ece965603" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 46019 } }
I20260812 06:19:57.132217 16672 raft_consensus.cc:385] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:57.132261 16672 raft_consensus.cc:740] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4e4d43c04cb74c708c53f76ece965603, State: Initialized, Role: FOLLOWER
I20260812 06:19:57.132520 16672 consensus_queue.cc:260] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [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: "4e4d43c04cb74c708c53f76ece965603" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 46019 } }
I20260812 06:19:57.132638 16672 raft_consensus.cc:399] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:57.132686 16672 raft_consensus.cc:493] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:57.132738 16672 raft_consensus.cc:3060] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:57.133770 16672 raft_consensus.cc:515] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e4d43c04cb74c708c53f76ece965603" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 46019 } }
I20260812 06:19:57.133927 16672 leader_election.cc:304] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [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: 4e4d43c04cb74c708c53f76ece965603; no voters: 
I20260812 06:19:57.134152 16672 leader_election.cc:290] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:57.134275 16679 raft_consensus.cc:2804] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:57.134521 16672 ts_tablet_manager.cc:1434] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Time spent starting tablet: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:57.134521 16679 raft_consensus.cc:697] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 1 LEADER]: Becoming Leader. State: Replica: 4e4d43c04cb74c708c53f76ece965603, State: Running, Role: LEADER
I20260812 06:19:57.134717 16679 consensus_queue.cc:237] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [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: "4e4d43c04cb74c708c53f76ece965603" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 46019 } }
I20260812 06:19:57.134886 16648 heartbeater.cc:499] Master 127.16.4.62:41921 was elected leader, sending a full tablet report...
I20260812 06:19:57.137507 16453 catalog_manager.cc:5719] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4e4d43c04cb74c708c53f76ece965603 (127.16.4.1). New cstate: current_term: 1 leader_uuid: "4e4d43c04cb74c708c53f76ece965603" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4e4d43c04cb74c708c53f76ece965603" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 46019 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:57.200474 16400 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.020s	sys 0.005s
I20260812 06:19:57.333542 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushMRSOp(2dc4c13b05d2482cb6e729211100507c): perf score=19.054940
I20260812 06:19:57.511754 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushMRSOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.178s	user 0.104s	sys 0.060s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":262,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":798,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41214,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":153,"threads_started":1,"update_count":1500}
I20260812 06:19:57.513051 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling LogGCOp(2dc4c13b05d2482cb6e729211100507c): free 20743880 bytes of WAL
I20260812 06:19:57.513392 16557 log_reader.cc:385] T 2dc4c13b05d2482cb6e729211100507c: removed 2 log segments from log reader
I20260812 06:19:57.513478 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000001 (ops 1-6)
I20260812 06:19:57.513538 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000002 (ops 7-11)
I20260812 06:19:57.518779 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: LogGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:57.519217 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:57.533294 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4803,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.533872 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:57.679154 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.145s	user 0.096s	sys 0.046s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":462,"lbm_read_time_us":8781,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24363,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":408,"threads_started":5,"update_count":2000}
I20260812 06:19:57.679862 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c): 16411395 bytes on disk
I20260812 06:19:57.680974 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.681907 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:57.717243 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.035s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15212,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.717756 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:57.733876 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5123,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.734381 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:57.861702 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.127s	user 0.111s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":506,"lbm_read_time_us":7663,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25051,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21888,"update_count":2000}
I20260812 06:19:57.862962 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:57.896147 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.033s	user 0.019s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.896704 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:57.910892 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.911378 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.032533 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.121s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2500,"lbm_read_time_us":10061,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22325,"lbm_writes_lt_1ms":443,"mutex_wait_us":889,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:58.033140 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:58.082695 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.049s	user 0.015s	sys 0.031s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16717,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.083346 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:58.099426 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6039,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.100085 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.251924 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.152s	user 0.089s	sys 0.059s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":497,"lbm_read_time_us":12032,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25226,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:58.252493 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:58.296394 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.044s	user 0.025s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15755,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.296906 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:58.307864 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3975,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.308543 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.442085 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.133s	user 0.100s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":4703,"lbm_read_time_us":10391,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23119,"lbm_writes_lt_1ms":443,"mutex_wait_us":4352,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.442742 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:58.488910 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.046s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17032,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.489388 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:58.499992 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3994,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.500435 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.618665 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.118s	user 0.077s	sys 0.041s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":212,"lbm_read_time_us":10353,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21127,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:19:58.619138 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:19:58.669585 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.050s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13962,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.670111 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:58.680549 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.681001 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushMRSOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.711089 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushMRSOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.030s	user 0.023s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1338,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1352,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:58.711915 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:58.854938 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.143s	user 0.101s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":277,"lbm_read_time_us":10393,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21940,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:58.855595 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling LogGCOp(2dc4c13b05d2482cb6e729211100507c): free 112239310 bytes of WAL
I20260812 06:19:58.855835 16557 log_reader.cc:385] T 2dc4c13b05d2482cb6e729211100507c: removed 11 log segments from log reader
I20260812 06:19:58.855886 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000003 (ops 12-16)
I20260812 06:19:58.855939 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000004 (ops 17-21)
I20260812 06:19:58.855978 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000005 (ops 22-26)
I20260812 06:19:58.856012 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000006 (ops 27-31)
I20260812 06:19:58.856046 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000007 (ops 32-36)
I20260812 06:19:58.856081 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000008 (ops 37-41)
I20260812 06:19:58.856113 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000009 (ops 42-46)
I20260812 06:19:58.856148 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000010 (ops 47-51)
I20260812 06:19:58.856180 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000011 (ops 52-56)
I20260812 06:19:58.856215 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000012 (ops 57-60)
I20260812 06:19:58.856248 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000013 (ops 61-65)
I20260812 06:19:58.880436 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: LogGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:19:58.880925 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:19:58.925760 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.045s	user 0.029s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19484,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:58.926337 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c): 447 bytes on disk
I20260812 06:19:58.926826 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.927333 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:58.943070 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5988,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.943557 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:59.124616 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.181s	user 0.107s	sys 0.056s 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":849,"lbm_read_time_us":11362,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30458,"lbm_writes_lt_1ms":543,"mutex_wait_us":87,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:59.125231 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:19:59.172063 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.046s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18605,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.172636 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:59.184652 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4440,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.185094 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:59.327831 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.143s	user 0.102s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":279,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29286,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:19:59.328498 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=11.118625
I20260812 06:19:59.376485 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.048s	user 0.020s	sys 0.025s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20202,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:59.377014 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:59.388481 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.389015 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:59.398895 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3519,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:59.399464 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:59.558751 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.159s	user 0.123s	sys 0.024s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":319,"lbm_read_time_us":10570,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29485,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13184,"update_count":2500}
I20260812 06:19:59.559422 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:19:59.615048 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.055s	user 0.036s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24466,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.615675 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:59.626641 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3778,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.627226 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:19:59.781637 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.154s	user 0.129s	sys 0.010s 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":353,"lbm_read_time_us":9959,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27183,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20096,"update_count":2500}
I20260812 06:19:59.782259 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:19:59.841600 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.059s	user 0.029s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21102,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.842262 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:19:59.852563 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3748,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.853037 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.024624 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.171s	user 0.106s	sys 0.060s 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":1007,"lbm_read_time_us":11008,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28034,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17280,"update_count":2500}
I20260812 06:20:00.025175 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:20:00.071754 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.046s	user 0.031s	sys 0.010s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20672,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.072376 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushMRSOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.104504 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushMRSOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.032s	user 0.031s	sys 0.001s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":208,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1565,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:20:00.105631 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling LogGCOp(2dc4c13b05d2482cb6e729211100507c): free 124710298 bytes of WAL
I20260812 06:20:00.105937 16557 log_reader.cc:385] T 2dc4c13b05d2482cb6e729211100507c: removed 12 log segments from log reader
I20260812 06:20:00.106029 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000014 (ops 66-70)
I20260812 06:20:00.106099 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000015 (ops 71-75)
I20260812 06:20:00.106148 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000016 (ops 76-80)
I20260812 06:20:00.106194 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000017 (ops 81-85)
I20260812 06:20:00.106256 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000018 (ops 86-90)
I20260812 06:20:00.106304 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000019 (ops 91-95)
I20260812 06:20:00.106350 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000020 (ops 96-100)
I20260812 06:20:00.106395 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000021 (ops 101-105)
I20260812 06:20:00.106441 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000022 (ops 106-110)
I20260812 06:20:00.106483 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000023 (ops 111-115)
I20260812 06:20:00.106526 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000024 (ops 116-120)
I20260812 06:20:00.106565 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000025 (ops 121-125)
I20260812 06:20:00.134356 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: LogGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.028s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:00.134820 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c): 472 bytes on disk
I20260812 06:20:00.135335 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.135900 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=5.165500
I20260812 06:20:00.157760 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.022s	user 0.009s	sys 0.011s Metrics: {"bytes_written":6851279,"delete_count":0,"lbm_write_time_us":8467,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:20:00.158388 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.168721 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":1353977,"delete_count":0,"lbm_write_time_us":2398,"lbm_writes_lt_1ms":36,"reinsert_count":0,"update_count":165}
I20260812 06:20:00.169150 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.359977 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.191s	user 0.147s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877154,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":639,"lbm_read_time_us":14149,"lbm_reads_lt_1ms":669,"lbm_write_time_us":33752,"lbm_writes_lt_1ms":643,"mutex_wait_us":47,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":160,"threads_started":1,"update_count":3000}
I20260812 06:20:00.362263 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:20:00.416291 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.054s	user 0.018s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19638,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.416788 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:00.427364 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.427979 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.609696 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.181s	user 0.122s	sys 0.050s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":132,"lbm_read_time_us":12356,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29802,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10240,"update_count":2500}
I20260812 06:20:00.610258 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:20:00.666007 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.056s	user 0.026s	sys 0.024s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":18831,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:00.666640 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:00.682204 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5841,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.682735 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:00.852140 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.169s	user 0.097s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":12566,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28316,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:00.852912 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=11.118625
I20260812 06:20:00.889464 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.036s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14778,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:00.889920 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:00.902874 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4758,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:00.903409 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.050241 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.147s	user 0.102s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":163,"lbm_read_time_us":10272,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22696,"lbm_writes_lt_1ms":443,"mutex_wait_us":2,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":35968,"update_count":2000}
I20260812 06:20:01.050973 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:20:01.082629 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.031s	user 0.020s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13150,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.083519 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:01.100008 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.100584 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.236891 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.136s	user 0.108s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":327,"dirs.run_cpu_time_us":1432,"dirs.run_wall_time_us":7953,"lbm_read_time_us":8844,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22345,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:20:01.237553 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=11.118625
I20260812 06:20:01.276005 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.038s	user 0.021s	sys 0.013s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":16392,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.276777 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:01.294302 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.017s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4802,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.294919 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.415277 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.120s	user 0.103s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":311,"lbm_read_time_us":8519,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21657,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:20:01.415850 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:20:01.474241 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.058s	user 0.013s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14213,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.474838 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:01.490670 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5788,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.491307 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.660008 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.168s	user 0.112s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":10558,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26839,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:20:01.660887 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=10.126437
I20260812 06:20:01.704320 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.043s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17985,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.704867 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:01.715133 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3725,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.715829 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushMRSOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.744580 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushMRSOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.029s	user 0.027s	sys 0.002s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":275,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1085,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1621,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:01.745267 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling LogGCOp(2dc4c13b05d2482cb6e729211100507c): free 132571585 bytes of WAL
I20260812 06:20:01.745491 16557 log_reader.cc:385] T 2dc4c13b05d2482cb6e729211100507c: removed 13 log segments from log reader
I20260812 06:20:01.745534 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000026 (ops 126-130)
I20260812 06:20:01.745563 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000027 (ops 131-135)
I20260812 06:20:01.745594 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000028 (ops 136-140)
I20260812 06:20:01.745625 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000029 (ops 141-145)
I20260812 06:20:01.745657 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000030 (ops 146-150)
I20260812 06:20:01.745689 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000031 (ops 151-154)
I20260812 06:20:01.745729 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000032 (ops 155-159)
I20260812 06:20:01.745762 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000033 (ops 160-164)
I20260812 06:20:01.745783 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000034 (ops 165-169)
I20260812 06:20:01.745812 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000035 (ops 170-174)
I20260812 06:20:01.745844 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000036 (ops 175-179)
I20260812 06:20:01.745874 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000037 (ops 180-184)
I20260812 06:20:01.745906 16557 log.cc:1079] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/2dc4c13b05d2482cb6e729211100507c/wal-000000038 (ops 185-188)
I20260812 06:20:01.770993 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: LogGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:01.771400 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=3.181125
I20260812 06:20:01.793972 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {"bytes_written":4635978,"delete_count":0,"lbm_write_time_us":4713,"lbm_writes_lt_1ms":116,"reinsert_count":0,"update_count":565}
I20260812 06:20:01.794559 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c): 483 bytes on disk
I20260812 06:20:01.795106 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: UndoDeltaBlockGCOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.795688 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:01.805775 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3569330,"delete_count":0,"lbm_write_time_us":3591,"lbm_writes_lt_1ms":90,"reinsert_count":0,"update_count":435}
I20260812 06:20:01.806252 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:01.998128 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.192s	user 0.089s	sys 0.099s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":162,"lbm_read_time_us":14441,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30434,"lbm_writes_lt_1ms":643,"mutex_wait_us":62,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:20:02.000559 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=14.095187
I20260812 06:20:02.045493 16400 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.845s	user 1.716s	sys 0.196s
I20260812 06:20:02.057425 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.056s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19061,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:02.058014 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c): perf score=2.188937
I20260812 06:20:02.074501 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: FlushDeltaMemStoresOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6604,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:20:02.075057 16649 maintenance_manager.cc:419] P 4e4d43c04cb74c708c53f76ece965603: Scheduling MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c): perf score=1.000000
I20260812 06:20:02.137658 16400 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.091s	user 0.003s	sys 0.000s
I20260812 06:20:02.138320 16400 tablet_server.cc:179] TabletServer@127.16.4.1:0 shutting down...
I20260812 06:20:02.210237 16557 maintenance_manager.cc:643] P 4e4d43c04cb74c708c53f76ece965603: MajorDeltaCompactionOp(2dc4c13b05d2482cb6e729211100507c) complete. Timing: real 0.135s	user 0.095s	sys 0.040s Metrics: {"cfile_cache_hit":264,"cfile_cache_hit_bytes":10791261,"cfile_cache_miss":268,"cfile_cache_miss_bytes":13983427,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":281,"lbm_read_time_us":7746,"lbm_reads_lt_1ms":300,"lbm_write_time_us":24814,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":19200,"update_count":2500}
I20260812 06:20:02.211156 16400 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:02.211649 16400 tablet_replica.cc:333] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603: stopping tablet replica
I20260812 06:20:02.211944 16400 raft_consensus.cc:2243] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.212203 16400 raft_consensus.cc:2272] T 2dc4c13b05d2482cb6e729211100507c P 4e4d43c04cb74c708c53f76ece965603 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.227751 16400 tablet_server.cc:196] TabletServer@127.16.4.1:0 shutdown complete.
I20260812 06:20:02.256950 16400 master.cc:562] Master@127.16.4.62:41921 shutting down...
I20260812 06:20:02.260479 16400 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.260684 16400 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.260759 16400 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7e538cb409cf49ad85f1066f95307507: stopping tablet replica
I20260812 06:20:02.274266 16400 master.cc:584] Master@127.16.4.62:41921 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5430 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:02.354442 16400 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.16.4.62:45275
I20260812 06:20:02.354866 16400 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.356941 16708 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:20:02.357034 16702 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:20:02.357141 16706 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:20:02.357275 16400 server_base.cc:1061] running on GCE node
I20260812 06:20:02.357435 16400 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.357481 16400 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:20:02.357496 16400 hybrid_clock.cc:648] HybridClock initialized: now 1786515602357496 us; error 0 us; skew 500 ppm
I20260812 06:20:02.358415 16400 webserver.cc:533] Webserver started at http://127.16.4.62:36217/ using document root <none> and password file <none>
I20260812 06:20:02.358592 16400 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.358654 16400 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.358750 16400 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.359196 16400 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/master-0-root/instance:
uuid: "4331c33f70db49c6975174180b0df3bf"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-lkx2"
I20260812 06:20:02.360857 16400 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:02.361878 16714 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:20:02.362128 16400 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:02.362216 16400 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/master-0-root
uuid: "4331c33f70db49c6975174180b0df3bf"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-lkx2"
I20260812 06:20:02.362303 16400 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-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:20:02.384492 16400 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.384958 16400 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.389607 16400 rpc_server.cc:307] RPC server started. Bound to: 127.16.4.62:45275
I20260812 06:20:02.402920 16802 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.4.62:45275 every 8 connection(s)
I20260812 06:20:02.403499 16803 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:20:02.405411 16803 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf: Bootstrap starting.
I20260812 06:20:02.406215 16803 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.407217 16803 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf: No bootstrap required, opened a new log
I20260812 06:20:02.407660 16803 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER }
I20260812 06:20:02.407835 16803 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.407898 16803 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4331c33f70db49c6975174180b0df3bf, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.408061 16803 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [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: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER }
I20260812 06:20:02.408174 16803 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.408219 16803 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.408270 16803 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.408996 16803 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER }
I20260812 06:20:02.409133 16803 leader_election.cc:304] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [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: 4331c33f70db49c6975174180b0df3bf; no voters: 
I20260812 06:20:02.409322 16803 leader_election.cc:290] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.409485 16806 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.409713 16806 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 1 LEADER]: Becoming Leader. State: Replica: 4331c33f70db49c6975174180b0df3bf, State: Running, Role: LEADER
I20260812 06:20:02.409799 16803 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:02.409854 16806 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [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: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER }
I20260812 06:20:02.410301 16810 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4331c33f70db49c6975174180b0df3bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER } }
I20260812 06:20:02.410399 16810 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.410354 16812 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4331c33f70db49c6975174180b0df3bf. Latest consensus state: current_term: 1 leader_uuid: "4331c33f70db49c6975174180b0df3bf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4331c33f70db49c6975174180b0df3bf" member_type: VOTER } }
I20260812 06:20:02.410442 16812 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.410712 16816 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:02.411576 16816 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:02.411755 16400 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:02.413395 16816 catalog_manager.cc:1383] Generated new cluster ID: 41d18abecea743fb8018425a8529ab47
I20260812 06:20:02.413451 16816 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:02.421943 16816 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:02.422454 16816 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:02.428376 16816 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf: Generated new TSK 0
I20260812 06:20:02.428522 16816 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:02.444227 16400 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.446300 16838 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:20:02.446301 16835 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:20:02.446365 16400 server_base.cc:1061] running on GCE node
W20260812 06:20:02.446519 16843 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:20:02.446771 16400 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.446813 16400 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:20:02.446864 16400 hybrid_clock.cc:648] HybridClock initialized: now 1786515602446864 us; error 0 us; skew 500 ppm
I20260812 06:20:02.447696 16400 webserver.cc:533] Webserver started at http://127.16.4.1:39637/ using document root <none> and password file <none>
I20260812 06:20:02.447880 16400 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.447933 16400 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.448014 16400 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.448454 16400 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/instance:
uuid: "b5048d7653534d7d97874cd175ea8268"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-lkx2"
I20260812 06:20:02.449926 16400 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:02.450924 16850 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:20:02.451179 16400 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:02.451251 16400 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root
uuid: "b5048d7653534d7d97874cd175ea8268"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-lkx2"
I20260812 06:20:02.451325 16400 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-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:20:02.473678 16400 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.474067 16400 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.474364 16400 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:02.474867 16400 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:02.474905 16400 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.474951 16400 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:02.474979 16400 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.478994 16400 rpc_server.cc:307] RPC server started. Bound to: 127.16.4.1:41435
I20260812 06:20:02.479595 16959 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.16.4.1:41435 every 8 connection(s)
I20260812 06:20:02.487802 16960 heartbeater.cc:344] Connected to a master server at 127.16.4.62:45275
I20260812 06:20:02.487916 16960 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:02.488118 16960 heartbeater.cc:507] Master 127.16.4.62:45275 requested a full tablet report, sending...
I20260812 06:20:02.488757 16742 ts_manager.cc:194] Registered new tserver with Master: b5048d7653534d7d97874cd175ea8268 (127.16.4.1:41435)
I20260812 06:20:02.489495 16742 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:56106
I20260812 06:20:02.489547 16400 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009871376s
I20260812 06:20:02.496730 16742 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:56118:
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:20:02.505139 16892 tablet_service.cc:1511] Processing CreateTablet for tablet 43d9fa2e927545fc86c030cfbe04b808 (DEFAULT_TABLE table=heavy-update-compaction-test [id=709036c6af104926b5cffa2962fe3191]), partition=
I20260812 06:20:02.505402 16892 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 43d9fa2e927545fc86c030cfbe04b808. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.507416 16975 tablet_bootstrap.cc:492] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Bootstrap starting.
I20260812 06:20:02.508369 16975 tablet_bootstrap.cc:654] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.509573 16975 tablet_bootstrap.cc:492] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: No bootstrap required, opened a new log
I20260812 06:20:02.509676 16975 ts_tablet_manager.cc:1403] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:02.510166 16975 raft_consensus.cc:359] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5048d7653534d7d97874cd175ea8268" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 41435 } }
I20260812 06:20:02.510273 16975 raft_consensus.cc:385] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.510349 16975 raft_consensus.cc:740] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b5048d7653534d7d97874cd175ea8268, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.510505 16975 consensus_queue.cc:260] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [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: "b5048d7653534d7d97874cd175ea8268" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 41435 } }
I20260812 06:20:02.510600 16975 raft_consensus.cc:399] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.510680 16975 raft_consensus.cc:493] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.510788 16975 raft_consensus.cc:3060] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.511560 16975 raft_consensus.cc:515] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5048d7653534d7d97874cd175ea8268" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 41435 } }
I20260812 06:20:02.511693 16975 leader_election.cc:304] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [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: b5048d7653534d7d97874cd175ea8268; no voters: 
I20260812 06:20:02.511860 16975 leader_election.cc:290] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.511997 16977 raft_consensus.cc:2804] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.512169 16975 ts_tablet_manager.cc:1434] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:20:02.512199 16960 heartbeater.cc:499] Master 127.16.4.62:45275 was elected leader, sending a full tablet report...
I20260812 06:20:02.512199 16977 raft_consensus.cc:697] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 1 LEADER]: Becoming Leader. State: Replica: b5048d7653534d7d97874cd175ea8268, State: Running, Role: LEADER
I20260812 06:20:02.512413 16977 consensus_queue.cc:237] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [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: "b5048d7653534d7d97874cd175ea8268" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 41435 } }
I20260812 06:20:02.513623 16742 catalog_manager.cc:5719] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 reported cstate change: term changed from 0 to 1, leader changed from <none> to b5048d7653534d7d97874cd175ea8268 (127.16.4.1). New cstate: current_term: 1 leader_uuid: "b5048d7653534d7d97874cd175ea8268" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b5048d7653534d7d97874cd175ea8268" member_type: VOTER last_known_addr { host: "127.16.4.1" port: 41435 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:02.573410 16400 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.015s	sys 0.008s
I20260812 06:20:02.730288 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808): perf score=19.054940
I20260812 06:20:02.875171 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.145s	user 0.098s	sys 0.043s Metrics: {"bytes_written":11897249,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":827,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":37166,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1450}
I20260812 06:20:02.876049 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling LogGCOp(43d9fa2e927545fc86c030cfbe04b808): free 20743880 bytes of WAL
I20260812 06:20:02.876405 16858 log_reader.cc:385] T 43d9fa2e927545fc86c030cfbe04b808: removed 2 log segments from log reader
I20260812 06:20:02.876466 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000001 (ops 1-6)
I20260812 06:20:02.876507 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000002 (ops 7-11)
I20260812 06:20:02.882126 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: LogGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.006s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:20:02.882480 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:02.907845 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.025s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4941,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.908450 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:02.921929 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5284,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.922537 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:03.103646 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.181s	user 0.136s	sys 0.032s Metrics: {"cfile_cache_miss":523,"cfile_cache_miss_bytes":24405562,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":543,"lbm_read_time_us":12390,"lbm_reads_lt_1ms":563,"lbm_write_time_us":25547,"lbm_writes_lt_1ms":533,"mutex_wait_us":25,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":4608,"thread_start_us":313,"threads_started":5,"update_count":2450}
I20260812 06:20:03.104215 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=14.095187
I20260812 06:20:03.151101 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.047s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19313,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.151558 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.162253 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3774,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.162922 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:03.305168 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.142s	user 0.116s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":198,"lbm_read_time_us":10208,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27191,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2500}
I20260812 06:20:03.305783 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=11.118625
I20260812 06:20:03.344334 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.038s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16460,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:03.345116 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808): 16821648 bytes on disk
I20260812 06:20:03.345815 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:20:03.346449 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.371500 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.025s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4824,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.371953 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.382447 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3923,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.382898 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:03.539279 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.156s	user 0.116s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1582,"lbm_read_time_us":9509,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31577,"lbm_writes_lt_1ms":543,"mutex_wait_us":526,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:20:03.539925 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=11.118625
I20260812 06:20:03.572788 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14071,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:03.573336 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.583464 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3350,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:03.584619 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:03.706532 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.122s	user 0.089s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":8376,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21612,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:20:03.707118 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:03.755894 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.049s	user 0.028s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17128,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.756496 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.767091 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3970,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.767503 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:03.923913 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.156s	user 0.124s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":131,"lbm_read_time_us":12150,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23102,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:20:03.924502 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:03.969051 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.044s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15414,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:03.969579 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:03.980607 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.981247 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.104537 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.123s	user 0.101s	sys 0.021s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":9096,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21855,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":17536,"update_count":2000}
I20260812 06:20:04.105057 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:04.135813 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13193,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.136327 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:04.151504 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5596,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.151953 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.183976 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.032s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":91,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1499,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2123,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:04.184715 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling LogGCOp(43d9fa2e927545fc86c030cfbe04b808): free 120553374 bytes of WAL
I20260812 06:20:04.185083 16858 log_reader.cc:385] T 43d9fa2e927545fc86c030cfbe04b808: removed 12 log segments from log reader
I20260812 06:20:04.185163 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000003 (ops 12-16)
I20260812 06:20:04.185251 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000004 (ops 17-21)
I20260812 06:20:04.185292 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000005 (ops 22-26)
I20260812 06:20:04.185323 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000006 (ops 27-30)
I20260812 06:20:04.185372 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000007 (ops 31-35)
I20260812 06:20:04.185421 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000008 (ops 36-40)
I20260812 06:20:04.185464 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000009 (ops 41-45)
I20260812 06:20:04.185513 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000010 (ops 46-50)
I20260812 06:20:04.185559 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000011 (ops 51-55)
I20260812 06:20:04.185603 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000012 (ops 56-60)
I20260812 06:20:04.185647 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000013 (ops 61-64)
I20260812 06:20:04.185693 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000014 (ops 65-69)
I20260812 06:20:04.210703 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: LogGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:20:04.211283 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808): 482 bytes on disk
I20260812 06:20:04.211787 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.212428 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=5.165500
I20260812 06:20:04.240674 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.028s	user 0.026s	sys 0.001s Metrics: {"bytes_written":7097423,"delete_count":0,"lbm_write_time_us":11251,"lbm_writes_lt_1ms":176,"reinsert_count":0,"update_count":865}
I20260812 06:20:04.241293 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling LogGCOp(43d9fa2e927545fc86c030cfbe04b808): free 8767123 bytes of WAL
I20260812 06:20:04.241540 16858 log_reader.cc:385] T 43d9fa2e927545fc86c030cfbe04b808: removed 1 log segments from log reader
I20260812 06:20:04.241607 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000015 (ops 70-74)
I20260812 06:20:04.243896 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: LogGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:04.244328 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.251343 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.007s	user 0.004s	sys 0.000s Metrics: {"bytes_written":1518081,"delete_count":0,"lbm_write_time_us":1815,"lbm_writes_lt_1ms":40,"reinsert_count":0,"update_count":185}
I20260812 06:20:04.251775 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.418990 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.167s	user 0.132s	sys 0.031s Metrics: {"cfile_cache_miss":644,"cfile_cache_miss_bytes":29328516,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":200,"lbm_read_time_us":13098,"lbm_reads_lt_1ms":676,"lbm_write_time_us":30585,"lbm_writes_lt_1ms":653,"mutex_wait_us":56,"peak_mem_usage":75952822,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":117,"threads_started":1,"update_count":3050}
I20260812 06:20:04.419685 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=14.095187
I20260812 06:20:04.456692 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.037s	user 0.022s	sys 0.015s Metrics: {"bytes_written":15999660,"delete_count":0,"lbm_write_time_us":15873,"lbm_writes_lt_1ms":393,"reinsert_count":0,"update_count":1950}
I20260812 06:20:04.457276 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:04.474169 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.017s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":500}
I20260812 06:20:04.474702 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.626673 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.152s	user 0.125s	sys 0.023s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24405442,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":657,"lbm_read_time_us":9238,"lbm_reads_lt_1ms":554,"lbm_write_time_us":30423,"lbm_writes_lt_1ms":533,"mutex_wait_us":357,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2450}
I20260812 06:20:04.627198 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=14.095187
I20260812 06:20:04.675414 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.048s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18278,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:04.675990 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:04.692276 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.016s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6013,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.692938 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:04.836889 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.144s	user 0.120s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":465,"lbm_read_time_us":9734,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30051,"lbm_writes_lt_1ms":543,"mutex_wait_us":304,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":24576,"update_count":2500}
I20260812 06:20:04.837508 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:04.869117 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.031s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13595,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:04.869621 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:04.885910 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5974,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.886461 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.012492 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.126s	user 0.090s	sys 0.033s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1451,"lbm_read_time_us":8112,"lbm_reads_lt_1ms":468,"lbm_write_time_us":26076,"lbm_writes_lt_1ms":443,"mutex_wait_us":426,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.013232 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=11.118625
I20260812 06:20:05.051955 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.039s	user 0.015s	sys 0.020s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":12679,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.052608 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:05.065452 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4771,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.065994 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.203644 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.137s	user 0.083s	sys 0.054s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":150,"lbm_read_time_us":9862,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22185,"lbm_writes_lt_1ms":443,"mutex_wait_us":61,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":15488,"update_count":2000}
I20260812 06:20:05.205065 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:05.241073 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.036s	user 0.017s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14408,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.241701 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:05.259989 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.018s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.260612 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.388911 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.128s	user 0.096s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":10256,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24376,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:20:05.389479 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:05.430411 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.041s	user 0.026s	sys 0.005s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14468,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.430987 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:05.441416 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.442130 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.571988 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.130s	user 0.106s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":653,"lbm_read_time_us":10215,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22909,"lbm_writes_lt_1ms":443,"mutex_wait_us":62,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5760,"update_count":2000}
I20260812 06:20:05.572639 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:05.605350 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.033s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14480,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":6016,"update_count":1500}
I20260812 06:20:05.605870 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.661564 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.056s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1281,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1623,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:05.662215 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling LogGCOp(43d9fa2e927545fc86c030cfbe04b808): free 124710331 bytes of WAL
I20260812 06:20:05.662436 16858 log_reader.cc:385] T 43d9fa2e927545fc86c030cfbe04b808: removed 12 log segments from log reader
I20260812 06:20:05.662479 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000016 (ops 75-79)
I20260812 06:20:05.662506 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000017 (ops 80-84)
I20260812 06:20:05.662532 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000018 (ops 85-89)
I20260812 06:20:05.662562 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000019 (ops 90-94)
I20260812 06:20:05.662596 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000020 (ops 95-99)
I20260812 06:20:05.662628 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000021 (ops 100-104)
I20260812 06:20:05.662657 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000022 (ops 105-109)
I20260812 06:20:05.662694 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000023 (ops 110-114)
I20260812 06:20:05.662716 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000024 (ops 115-119)
I20260812 06:20:05.662746 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000025 (ops 120-124)
I20260812 06:20:05.662779 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000026 (ops 125-129)
I20260812 06:20:05.662811 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000027 (ops 130-134)
I20260812 06:20:05.685767 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: LogGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.023s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:20:05.686264 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808): 482 bytes on disk
I20260812 06:20:05.686717 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.687363 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=7.149875
I20260812 06:20:05.707108 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8076,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:20:05.707612 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:05.719871 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4476,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.720335 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:05.883948 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.163s	user 0.138s	sys 0.025s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918210,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":265,"lbm_read_time_us":11646,"lbm_reads_lt_1ms":665,"lbm_write_time_us":33030,"lbm_writes_lt_1ms":643,"mutex_wait_us":71,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25344,"thread_start_us":74,"threads_started":1,"update_count":3000}
I20260812 06:20:05.884498 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=14.095187
I20260812 06:20:05.941233 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.057s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18567,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.942049 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:05.955080 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.955590 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:06.104480 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.149s	user 0.094s	sys 0.049s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1204,"lbm_read_time_us":9184,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27495,"lbm_writes_lt_1ms":543,"mutex_wait_us":370,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:20:06.105103 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=14.095187
I20260812 06:20:06.152415 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.047s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.153041 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:06.289170 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.136s	user 0.092s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713153,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":840,"lbm_read_time_us":9464,"lbm_reads_lt_1ms":467,"lbm_write_time_us":21212,"lbm_writes_lt_1ms":443,"mutex_wait_us":303,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:20:06.289719 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=11.118625
I20260812 06:20:06.329437 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.039s	user 0.027s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16656,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.330004 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:06.342926 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.013s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4932,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.343457 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:06.470450 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.127s	user 0.082s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":317,"lbm_read_time_us":7740,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25214,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.471163 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=11.118625
I20260812 06:20:06.516511 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.045s	user 0.020s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":19678,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:20:06.517311 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:06.537093 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.020s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4658,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.537581 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:06.546720 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3188,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:06.547268 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:06.720741 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.173s	user 0.137s	sys 0.036s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":375,"lbm_read_time_us":12439,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34349,"lbm_writes_lt_1ms":543,"mutex_wait_us":3,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2500}
I20260812 06:20:06.722223 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:06.780694 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.058s	user 0.034s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":22716,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:06.781411 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:06.799718 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":6906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.800421 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:06.989539 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.189s	user 0.142s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":570,"lbm_read_time_us":13259,"lbm_reads_lt_1ms":472,"lbm_write_time_us":37042,"lbm_writes_lt_1ms":443,"mutex_wait_us":101,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26496,"update_count":2000}
I20260812 06:20:06.990494 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=10.126437
I20260812 06:20:07.068336 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.077s	user 0.055s	sys 0.015s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":25550,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.069548 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:07.088989 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.019s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.089757 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:07.136023 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushMRSOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.046s	user 0.042s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":277,"dirs.run_wall_time_us":1352,"drs_written":1,"lbm_read_time_us":125,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:20:07.137931 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808): perf score=1.000000
I20260812 06:20:07.409919 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: MajorDeltaCompactionOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.272s	user 0.163s	sys 0.083s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1373,"lbm_read_time_us":12930,"lbm_reads_lt_1ms":464,"lbm_write_time_us":46947,"lbm_writes_lt_1ms":443,"mutex_wait_us":394,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:20:07.411223 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling LogGCOp(43d9fa2e927545fc86c030cfbe04b808): free 123804445 bytes of WAL
I20260812 06:20:07.411794 16858 log_reader.cc:385] T 43d9fa2e927545fc86c030cfbe04b808: removed 12 log segments from log reader
I20260812 06:20:07.411898 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000028 (ops 135-139)
I20260812 06:20:07.412014 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000029 (ops 140-144)
I20260812 06:20:07.412077 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000030 (ops 145-149)
I20260812 06:20:07.412187 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000031 (ops 150-154)
I20260812 06:20:07.412264 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000032 (ops 155-159)
I20260812 06:20:07.412393 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000033 (ops 160-164)
I20260812 06:20:07.412456 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000034 (ops 165-169)
I20260812 06:20:07.412554 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000035 (ops 170-174)
I20260812 06:20:07.412619 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000036 (ops 175-178)
I20260812 06:20:07.412708 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000037 (ops 179-183)
I20260812 06:20:07.412760 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000038 (ops 184-188)
I20260812 06:20:07.412848 16858 log.cc:1079] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: Deleting log segment in path: /tmp/dist-test-taskhbjh_q/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596913313-16400-0/minicluster-data/ts-0-root/wals/43d9fa2e927545fc86c030cfbe04b808/wal-000000039 (ops 189-192)
I20260812 06:20:07.454615 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: LogGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.043s	user 0.000s	sys 0.041s Metrics: {}
I20260812 06:20:07.455471 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=15.087375
I20260812 06:20:07.487042 16400 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.914s	user 1.820s	sys 0.121s
I20260812 06:20:07.524250 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.068s	user 0.047s	sys 0.018s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":30174,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:20:07.525240 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808): 448 bytes on disk
I20260812 06:20:07.526580 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: UndoDeltaBlockGCOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":124,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.527557 16961 maintenance_manager.cc:419] P b5048d7653534d7d97874cd175ea8268: Scheduling FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808): perf score=2.188937
I20260812 06:20:07.530725 16400 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.043s	user 0.002s	sys 0.000s
I20260812 06:20:07.531374 16400 tablet_server.cc:179] TabletServer@127.16.4.1:0 shutting down...
I20260812 06:20:07.547695 16858 maintenance_manager.cc:643] P b5048d7653534d7d97874cd175ea8268: FlushDeltaMemStoresOp(43d9fa2e927545fc86c030cfbe04b808) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7655,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:07.548470 16400 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:07.548969 16400 tablet_replica.cc:333] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268: stopping tablet replica
I20260812 06:20:07.549212 16400 raft_consensus.cc:2243] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.549429 16400 raft_consensus.cc:2272] T 43d9fa2e927545fc86c030cfbe04b808 P b5048d7653534d7d97874cd175ea8268 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.554276 16400 tablet_server.cc:196] TabletServer@127.16.4.1:0 shutdown complete.
I20260812 06:20:07.558323 16400 master.cc:562] Master@127.16.4.62:45275 shutting down...
I20260812 06:20:07.563313 16400 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.563561 16400 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.563655 16400 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4331c33f70db49c6975174180b0df3bf: stopping tablet replica
I20260812 06:20:07.577150 16400 master.cc:584] Master@127.16.4.62:45275 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5328 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10760 ms total)

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