[==========] 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:16:29.150108 13425 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.28.126:37545
I20260812 06:16:29.150987 13425 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:16:29.151494 13425 file_cache.cc:504] Constructed file cache file cache with capacity 419430
I20260812 06:16:29.157579 13425 server_base.cc:1061] running on GCE node
W20260812 06:16:29.157605 13435 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:16:29.157809 13439 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:16:29.157936 13432 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:16:29.158440 13425 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.158524 13425 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:16:29.158584 13425 hybrid_clock.cc:648] HybridClock initialized: now 1786515389158581 us; error 0 us; skew 500 ppm
I20260812 06:16:29.160239 13425 webserver.cc:533] Webserver started at http://127.13.28.126:42193/ using document root <none> and password file <none>
I20260812 06:16:29.160728 13425 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.160784 13425 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.161033 13425 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.162583 13425 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/master-0-root/instance:
uuid: "b6130061d9a54f9c9190ed2f2d2c9396"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-znh6"
I20260812 06:16:29.165755 13425 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:16:29.167703 13449 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:16:29.168615 13425 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:29.168742 13425 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/master-0-root
uuid: "b6130061d9a54f9c9190ed2f2d2c9396"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-znh6"
I20260812 06:16:29.168841 13425 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-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:16:29.180442 13425 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.180986 13425 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:16:29.181154 13425 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.188657 13425 rpc_server.cc:307] RPC server started. Bound to: 127.13.28.126:37545
I20260812 06:16:29.188678 13550 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.28.126:37545 every 8 connection(s)
I20260812 06:16:29.190693 13553 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:16:29.195838 13553 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: Bootstrap starting.
I20260812 06:16:29.198028 13553 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.198954 13553 log.cc:826] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:29.200464 13553 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: No bootstrap required, opened a new log
I20260812 06:16:29.203097 13553 raft_consensus.cc:359] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER }
I20260812 06:16:29.203262 13553 raft_consensus.cc:385] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.203377 13553 raft_consensus.cc:740] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b6130061d9a54f9c9190ed2f2d2c9396, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.203920 13553 consensus_queue.cc:260] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [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: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER }
I20260812 06:16:29.204082 13553 raft_consensus.cc:399] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.204159 13553 raft_consensus.cc:493] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.204320 13553 raft_consensus.cc:3060] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.205070 13553 raft_consensus.cc:515] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER }
I20260812 06:16:29.205477 13553 leader_election.cc:304] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [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: b6130061d9a54f9c9190ed2f2d2c9396; no voters: 
I20260812 06:16:29.205775 13553 leader_election.cc:290] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.205917 13557 raft_consensus.cc:2804] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.206162 13557 raft_consensus.cc:697] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 1 LEADER]: Becoming Leader. State: Replica: b6130061d9a54f9c9190ed2f2d2c9396, State: Running, Role: LEADER
I20260812 06:16:29.206576 13557 consensus_queue.cc:237] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [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: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER }
I20260812 06:16:29.206683 13553 sys_catalog.cc:565] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:29.208463 13560 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER } }
I20260812 06:16:29.208431 13563 sys_catalog.cc:455] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [sys.catalog]: SysCatalogTable state changed. Reason: New leader b6130061d9a54f9c9190ed2f2d2c9396. Latest consensus state: current_term: 1 leader_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b6130061d9a54f9c9190ed2f2d2c9396" member_type: VOTER } }
I20260812 06:16:29.208556 13560 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.208556 13563 sys_catalog.cc:458] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:29.208986 13583 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:29.209009 13425 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:29.211488 13583 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:29.215889 13583 catalog_manager.cc:1383] Generated new cluster ID: 5b90d9d357894c10b88f66c94505c64a
I20260812 06:16:29.215953 13583 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:29.224331 13583 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:29.225052 13583 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:29.232338 13583 catalog_manager.cc:6092] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: Generated new TSK 0
I20260812 06:16:29.232841 13583 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:29.241484 13425 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:29.244314 13600 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:16:29.244364 13594 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:16:29.244539 13425 server_base.cc:1061] running on GCE node
W20260812 06:16:29.244586 13595 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:16:29.244861 13425 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:29.244905 13425 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:16:29.244922 13425 hybrid_clock.cc:648] HybridClock initialized: now 1786515389244922 us; error 0 us; skew 500 ppm
I20260812 06:16:29.245875 13425 webserver.cc:533] Webserver started at http://127.13.28.65:44505/ using document root <none> and password file <none>
I20260812 06:16:29.246052 13425 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:29.246111 13425 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:29.246204 13425 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:29.246595 13425 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/instance:
uuid: "96d93c2465f34183b92b22ff072af50b"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-znh6"
I20260812 06:16:29.248215 13425 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.249200 13613 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:16:29.249449 13425 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:29.249517 13425 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root
uuid: "96d93c2465f34183b92b22ff072af50b"
format_stamp: "Formatted at 2026-08-12 06:16:29 on dist-test-slave-znh6"
I20260812 06:16:29.249599 13425 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-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:16:29.258533 13425 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:29.258985 13425 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:29.259378 13425 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:29.260183 13425 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:29.260233 13425 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.260296 13425 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:29.260337 13425 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:29.267354 13425 rpc_server.cc:307] RPC server started. Bound to: 127.13.28.65:41931
I20260812 06:16:29.267390 13716 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.28.65:41931 every 8 connection(s)
I20260812 06:16:29.281952 13717 heartbeater.cc:344] Connected to a master server at 127.13.28.126:37545
I20260812 06:16:29.282187 13717 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:29.282603 13717 heartbeater.cc:507] Master 127.13.28.126:37545 requested a full tablet report, sending...
I20260812 06:16:29.284103 13489 ts_manager.cc:194] Registered new tserver with Master: 96d93c2465f34183b92b22ff072af50b (127.13.28.65:41931)
I20260812 06:16:29.284564 13425 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016610049s
I20260812 06:16:29.286034 13489 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:40092
I20260812 06:16:29.293249 13489 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:40104:
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:16:29.307278 13663 tablet_service.cc:1511] Processing CreateTablet for tablet 63ae2f90cbc24c2397b09fe28d626029 (DEFAULT_TABLE table=heavy-update-compaction-test [id=80aefc88481b4d34aa55a9642a7e11f3]), partition=
I20260812 06:16:29.307735 13663 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 63ae2f90cbc24c2397b09fe28d626029. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:29.310429 13735 tablet_bootstrap.cc:492] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Bootstrap starting.
I20260812 06:16:29.311372 13735 tablet_bootstrap.cc:654] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:29.312423 13735 tablet_bootstrap.cc:492] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: No bootstrap required, opened a new log
I20260812 06:16:29.312544 13735 ts_tablet_manager.cc:1403] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:29.312950 13735 raft_consensus.cc:359] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96d93c2465f34183b92b22ff072af50b" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 41931 } }
I20260812 06:16:29.313079 13735 raft_consensus.cc:385] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:29.313146 13735 raft_consensus.cc:740] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 96d93c2465f34183b92b22ff072af50b, State: Initialized, Role: FOLLOWER
I20260812 06:16:29.313311 13735 consensus_queue.cc:260] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [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: "96d93c2465f34183b92b22ff072af50b" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 41931 } }
I20260812 06:16:29.313428 13735 raft_consensus.cc:399] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:29.313480 13735 raft_consensus.cc:493] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:29.313551 13735 raft_consensus.cc:3060] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:29.314498 13735 raft_consensus.cc:515] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96d93c2465f34183b92b22ff072af50b" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 41931 } }
I20260812 06:16:29.314651 13735 leader_election.cc:304] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [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: 96d93c2465f34183b92b22ff072af50b; no voters: 
I20260812 06:16:29.314895 13735 leader_election.cc:290] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:29.314985 13737 raft_consensus.cc:2804] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:29.315165 13737 raft_consensus.cc:697] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 1 LEADER]: Becoming Leader. State: Replica: 96d93c2465f34183b92b22ff072af50b, State: Running, Role: LEADER
I20260812 06:16:29.315279 13735 ts_tablet_manager.cc:1434] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:29.315363 13737 consensus_queue.cc:237] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [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: "96d93c2465f34183b92b22ff072af50b" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 41931 } }
I20260812 06:16:29.315459 13717 heartbeater.cc:499] Master 127.13.28.126:37545 was elected leader, sending a full tablet report...
I20260812 06:16:29.317813 13489 catalog_manager.cc:5719] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b reported cstate change: term changed from 0 to 1, leader changed from <none> to 96d93c2465f34183b92b22ff072af50b (127.13.28.65). New cstate: current_term: 1 leader_uuid: "96d93c2465f34183b92b22ff072af50b" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "96d93c2465f34183b92b22ff072af50b" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 41931 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:29.418260 13425 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.092s	user 0.018s	sys 0.033s
I20260812 06:16:29.518461 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029): perf score=15.086190
I20260812 06:16:29.690177 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.171s	user 0.121s	sys 0.047s Metrics: {"bytes_written":9148636,"cfile_init":1,"compiler_manager_pool.queue_time_us":192,"delete_count":0,"dirs.queue_time_us":92,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":2235,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":59424,"lbm_writes_lt_1ms":580,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":117,"threads_started":1,"update_count":1115}
I20260812 06:16:29.691416 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 11976772 bytes of WAL
I20260812 06:16:29.691789 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 1 log segments from log reader
I20260812 06:16:29.691915 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000001 (ops 1-6)
I20260812 06:16:29.695215 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:29.695513 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.196750
I20260812 06:16:29.712495 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.017s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3159080,"delete_count":0,"lbm_write_time_us":4261,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:16:29.712915 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:29.727839 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.015s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.728511 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029): 12308958 bytes on disk
I20260812 06:16:29.729090 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:29.729537 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:29.875563 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.146s	user 0.126s	sys 0.012s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20631410,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":844,"lbm_read_time_us":8793,"lbm_reads_lt_1ms":469,"lbm_write_time_us":27858,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":329,"threads_started":5,"update_count":2000}
I20260812 06:16:29.876194 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:29.923076 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.047s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17765,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:29.923590 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:29.935026 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4192,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:29.935438 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.057015 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.121s	user 0.083s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":678,"lbm_read_time_us":8902,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25220,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"update_count":2000}
I20260812 06:16:30.057549 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:30.110045 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.052s	user 0.019s	sys 0.021s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15996,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.110605 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:30.126861 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.016s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.127364 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.286171 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.159s	user 0.108s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":134,"lbm_read_time_us":11302,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26102,"lbm_writes_lt_1ms":443,"mutex_wait_us":21,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:16:30.286891 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:30.335244 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.048s	user 0.019s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17625,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.335723 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:30.350870 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.015s	user 0.007s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.351404 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.486246 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.135s	user 0.122s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1204,"lbm_read_time_us":9785,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28397,"lbm_writes_lt_1ms":443,"mutex_wait_us":299,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:16:30.486948 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:30.531057 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.044s	user 0.013s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15417,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.531513 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:30.547111 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5885,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.547567 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.677867 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.130s	user 0.105s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1085,"lbm_read_time_us":10379,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25526,"lbm_writes_lt_1ms":443,"mutex_wait_us":356,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2000}
I20260812 06:16:30.678571 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:30.728441 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.050s	user 0.023s	sys 0.021s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16641,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.729030 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:30.739688 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.010s	user 0.004s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.740234 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.886915 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.146s	user 0.094s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":923,"lbm_read_time_us":10980,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25126,"lbm_writes_lt_1ms":443,"mutex_wait_us":261,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2000}
I20260812 06:16:30.887548 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:30.931298 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.044s	user 0.014s	sys 0.029s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17985,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:30.931730 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:30.942940 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4075,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:30.943452 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:30.973223 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.030s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1152509,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1367,"drs_written":1,"lbm_read_time_us":121,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1519,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:30.973978 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 112692314 bytes of WAL
I20260812 06:16:30.974195 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 11 log segments from log reader
I20260812 06:16:30.974255 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000002 (ops 7-11)
I20260812 06:16:30.974308 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000003 (ops 12-16)
I20260812 06:16:30.974366 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000004 (ops 17-21)
I20260812 06:16:30.974408 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000005 (ops 22-26)
I20260812 06:16:30.974454 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000006 (ops 27-31)
I20260812 06:16:30.974491 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000007 (ops 32-36)
I20260812 06:16:30.974524 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000008 (ops 37-41)
I20260812 06:16:30.974560 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000009 (ops 42-46)
I20260812 06:16:30.974597 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000010 (ops 47-51)
I20260812 06:16:30.974634 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000011 (ops 52-56)
I20260812 06:16:30.974671 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000012 (ops 57-61)
I20260812 06:16:31.000186 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:31.000698 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029): 447 bytes on disk
I20260812 06:16:31.001223 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029) 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:16:31.001688 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=5.165500
I20260812 06:16:31.024185 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.022s	user 0.009s	sys 0.012s Metrics: {"bytes_written":6358990,"delete_count":0,"lbm_write_time_us":6236,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:16:31.024714 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 12017983 bytes of WAL
I20260812 06:16:31.024969 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 1 log segments from log reader
I20260812 06:16:31.025039 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000013 (ops 62-66)
I20260812 06:16:31.027537 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:31.027930 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:31.033571 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.005s	user 0.003s	sys 0.001s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":1772,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:16:31.033926 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:31.232898 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.199s	user 0.117s	sys 0.079s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836318,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":167,"lbm_read_time_us":13469,"lbm_reads_lt_1ms":674,"lbm_write_time_us":36591,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:16:31.233395 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=14.095187
I20260812 06:16:31.297138 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.064s	user 0.014s	sys 0.046s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":25604,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.297640 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:31.308465 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.308871 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:31.477980 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.169s	user 0.111s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733719,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":300,"lbm_read_time_us":11745,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30600,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2500}
I20260812 06:16:31.478641 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:31.525676 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.047s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":22457,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.526150 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:31.538486 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.539124 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:31.681625 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.142s	user 0.106s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":919,"lbm_read_time_us":9034,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27220,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:31.682210 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:31.737906 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.055s	user 0.018s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20604,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:31.738495 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:31.754899 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.016s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6411,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.755527 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:31.890938 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.135s	user 0.111s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1351,"lbm_read_time_us":10788,"lbm_reads_lt_1ms":464,"lbm_write_time_us":28564,"lbm_writes_lt_1ms":443,"mutex_wait_us":313,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24704,"update_count":2000}
I20260812 06:16:31.891467 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:31.934541 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.043s	user 0.026s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16912,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:16:31.935039 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:31.946484 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:31.947117 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:32.070524 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.123s	user 0.106s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631314,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":183,"lbm_read_time_us":7710,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25442,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:16:32.071273 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:32.118527 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.047s	user 0.024s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17596,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:32.119128 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:32.136045 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6461,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.138303 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:32.290714 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.152s	user 0.112s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":925,"lbm_read_time_us":10479,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28424,"lbm_writes_lt_1ms":443,"mutex_wait_us":307,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2000}
I20260812 06:16:32.291407 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:32.325160 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.034s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:32.325769 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:32.344897 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.345361 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:32.395629 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.050s	user 0.022s	sys 0.006s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":205,"dirs.run_wall_time_us":1381,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2206,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:16:32.396373 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 100221341 bytes of WAL
I20260812 06:16:32.396598 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 10 log segments from log reader
I20260812 06:16:32.396642 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000014 (ops 67-71)
I20260812 06:16:32.396697 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000015 (ops 72-76)
I20260812 06:16:32.396741 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000016 (ops 77-81)
I20260812 06:16:32.396816 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000017 (ops 82-86)
I20260812 06:16:32.396876 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000018 (ops 87-91)
I20260812 06:16:32.396919 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000019 (ops 92-96)
I20260812 06:16:32.396960 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000020 (ops 97-100)
I20260812 06:16:32.396999 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000021 (ops 101-105)
I20260812 06:16:32.397037 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000022 (ops 106-110)
I20260812 06:16:32.397075 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000023 (ops 111-115)
I20260812 06:16:32.421766 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.025s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:32.422194 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=6.157687
I20260812 06:16:32.448269 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.026s	user 0.004s	sys 0.016s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9118,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:32.448746 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 8767174 bytes of WAL
I20260812 06:16:32.448987 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 1 log segments from log reader
I20260812 06:16:32.449059 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000024 (ops 116-120)
I20260812 06:16:32.451422 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:32.451756 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029): 447 bytes on disk
I20260812 06:16:32.452143 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:32.452620 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:32.462574 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3962,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.463001 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:32.675436 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.212s	user 0.148s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32938787,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":180,"lbm_read_time_us":14296,"lbm_reads_lt_1ms":774,"lbm_write_time_us":36573,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:16:32.675984 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=14.095187
I20260812 06:16:32.728209 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.052s	user 0.034s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20872,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:32.728675 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:32.754276 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.025s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6784,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.754716 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:32.764796 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3961,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:32.765201 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:32.965947 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.201s	user 0.108s	sys 0.080s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836254,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":732,"lbm_read_time_us":12886,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34273,"lbm_writes_lt_1ms":643,"mutex_wait_us":3,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":50432,"update_count":3000}
I20260812 06:16:32.966501 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=18.063937
I20260812 06:16:33.030207 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.063s	user 0.030s	sys 0.029s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28637,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:33.030659 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:33.042125 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3920,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.042778 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:33.234555 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.191s	user 0.122s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836138,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":593,"lbm_read_time_us":14116,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35317,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3000}
I20260812 06:16:33.235220 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=15.087375
I20260812 06:16:33.282805 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.047s	user 0.037s	sys 0.007s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":21960,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:33.283506 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:33.304103 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.020s	user 0.013s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5575,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.304548 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:33.315013 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.010s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4236,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.315423 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:33.478547 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.163s	user 0.118s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836240,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":803,"lbm_read_time_us":12042,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35507,"lbm_writes_lt_1ms":643,"mutex_wait_us":324,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":3000}
I20260812 06:16:33.479318 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=14.095187
I20260812 06:16:33.525278 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.046s	user 0.032s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20744,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.525840 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:33.538414 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4559,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:33.539034 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:33.703892 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.165s	user 0.100s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":288,"lbm_read_time_us":10800,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31002,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"update_count":2500}
I20260812 06:16:33.704560 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=14.095187
I20260812 06:16:33.766748 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.062s	user 0.033s	sys 0.019s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":25084,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:33.767328 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:33.821972 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushMRSOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.054s	user 0.029s	sys 0.005s Metrics: {"bytes_written":1234476,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":312,"dirs.run_wall_time_us":3119,"drs_written":1,"lbm_read_time_us":1851,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":3,"lbm_write_time_us":1611,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:16:33.822685 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling LogGCOp(63ae2f90cbc24c2397b09fe28d626029): free 123804409 bytes of WAL
I20260812 06:16:33.822970 13624 log_reader.cc:385] T 63ae2f90cbc24c2397b09fe28d626029: removed 12 log segments from log reader
I20260812 06:16:33.823036 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000025 (ops 121-124)
I20260812 06:16:33.823072 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000026 (ops 125-129)
I20260812 06:16:33.823099 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000027 (ops 130-134)
I20260812 06:16:33.823129 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000028 (ops 135-139)
I20260812 06:16:33.823155 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000029 (ops 140-144)
I20260812 06:16:33.823186 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000030 (ops 145-149)
I20260812 06:16:33.823226 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000031 (ops 150-154)
I20260812 06:16:33.823256 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000032 (ops 155-159)
I20260812 06:16:33.823285 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000033 (ops 160-164)
I20260812 06:16:33.823312 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000034 (ops 165-168)
I20260812 06:16:33.823342 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000035 (ops 169-173)
I20260812 06:16:33.823376 13624 log.cc:1079] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/63ae2f90cbc24c2397b09fe28d626029/wal-000000036 (ops 174-178)
I20260812 06:16:33.853729 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: LogGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.031s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:16:33.856032 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029): 472 bytes on disk
I20260812 06:16:33.856489 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: UndoDeltaBlockGCOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:16:33.857100 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=7.149875
I20260812 06:16:33.878376 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.021s	user 0.005s	sys 0.013s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":8770,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:16:33.878800 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:33.888211 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3531,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:33.888597 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:34.099159 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.210s	user 0.127s	sys 0.073s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32938661,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":666,"lbm_read_time_us":16119,"lbm_reads_lt_1ms":773,"lbm_write_time_us":36485,"lbm_writes_lt_1ms":743,"mutex_wait_us":78,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:16:34.099813 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=18.063937
I20260812 06:16:34.160869 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.061s	user 0.030s	sys 0.028s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":27959,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:34.161365 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=2.188937
I20260812 06:16:34.180095 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.019s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6114,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:34.180692 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029): perf score=1.000000
I20260812 06:16:34.273535 13425 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.855s	user 1.773s	sys 0.141s
I20260812 06:16:34.330672 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: MajorDeltaCompactionOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.150s	user 0.124s	sys 0.025s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28836136,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2080,"lbm_read_time_us":11293,"lbm_reads_lt_1ms":660,"lbm_write_time_us":32550,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:34.331369 13718 maintenance_manager.cc:419] P 96d93c2465f34183b92b22ff072af50b: Scheduling FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029): perf score=10.126437
I20260812 06:16:34.336619 13425 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.062s	user 0.004s	sys 0.000s
I20260812 06:16:34.337245 13425 tablet_server.cc:179] TabletServer@127.13.28.65:0 shutting down...
I20260812 06:16:34.365202 13624 maintenance_manager.cc:643] P 96d93c2465f34183b92b22ff072af50b: FlushDeltaMemStoresOp(63ae2f90cbc24c2397b09fe28d626029) complete. Timing: real 0.034s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:34.365777 13425 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:34.366521 13425 tablet_replica.cc:333] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b: stopping tablet replica
I20260812 06:16:34.366744 13425 raft_consensus.cc:2243] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.367002 13425 raft_consensus.cc:2272] T 63ae2f90cbc24c2397b09fe28d626029 P 96d93c2465f34183b92b22ff072af50b [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.382717 13425 tablet_server.cc:196] TabletServer@127.13.28.65:0 shutdown complete.
I20260812 06:16:34.387105 13425 master.cc:562] Master@127.13.28.126:37545 shutting down...
I20260812 06:16:34.390429 13425 raft_consensus.cc:2243] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:34.390553 13425 raft_consensus.cc:2272] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:34.390595 13425 tablet_replica.cc:333] T 00000000000000000000000000000000 P b6130061d9a54f9c9190ed2f2d2c9396: stopping tablet replica
I20260812 06:16:34.402660 13425 master.cc:584] Master@127.13.28.126:37545 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5347 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:34.497902 13425 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.13.28.126:41701
I20260812 06:16:34.498332 13425 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.500586 13768 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:16:34.500697 13769 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:16:34.500725 13772 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:16:34.500797 13425 server_base.cc:1061] running on GCE node
I20260812 06:16:34.501147 13425 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.501207 13425 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:16:34.501235 13425 hybrid_clock.cc:648] HybridClock initialized: now 1786515394501234 us; error 0 us; skew 500 ppm
I20260812 06:16:34.502197 13425 webserver.cc:533] Webserver started at http://127.13.28.126:45239/ using document root <none> and password file <none>
I20260812 06:16:34.502374 13425 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.502450 13425 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.502529 13425 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.503002 13425 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/master-0-root/instance:
uuid: "1a41d396b38b400a9b96c3b82250efab"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-znh6"
I20260812 06:16:34.504513 13425 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:34.505376 13783 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:16:34.505642 13425 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:34.505738 13425 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/master-0-root
uuid: "1a41d396b38b400a9b96c3b82250efab"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-znh6"
I20260812 06:16:34.505825 13425 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-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:16:34.526718 13425 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.527110 13425 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.531141 13425 rpc_server.cc:307] RPC server started. Bound to: 127.13.28.126:41701
I20260812 06:16:34.533311 13869 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:16:34.539597 13867 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.28.126:41701 every 8 connection(s)
I20260812 06:16:34.548833 13869 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab: Bootstrap starting.
I20260812 06:16:34.549624 13869 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.550614 13869 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab: No bootstrap required, opened a new log
I20260812 06:16:34.551033 13869 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER }
I20260812 06:16:34.551141 13869 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.551186 13869 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1a41d396b38b400a9b96c3b82250efab, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.551359 13869 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [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: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER }
I20260812 06:16:34.551465 13869 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.551517 13869 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.551575 13869 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.552235 13869 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER }
I20260812 06:16:34.552390 13869 leader_election.cc:304] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [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: 1a41d396b38b400a9b96c3b82250efab; no voters: 
I20260812 06:16:34.552591 13869 leader_election.cc:290] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.552721 13877 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.552969 13877 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 1 LEADER]: Becoming Leader. State: Replica: 1a41d396b38b400a9b96c3b82250efab, State: Running, Role: LEADER
I20260812 06:16:34.553064 13869 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:34.553102 13877 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [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: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER }
I20260812 06:16:34.553534 13880 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1a41d396b38b400a9b96c3b82250efab. Latest consensus state: current_term: 1 leader_uuid: "1a41d396b38b400a9b96c3b82250efab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER } }
I20260812 06:16:34.553668 13880 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:34.553514 13879 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1a41d396b38b400a9b96c3b82250efab" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1a41d396b38b400a9b96c3b82250efab" member_type: VOTER } }
I20260812 06:16:34.553990 13879 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:34.554060 13893 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:34.554781 13893 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:34.555083 13425 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:34.556629 13893 catalog_manager.cc:1383] Generated new cluster ID: 9db498b304b04b6cb9db5b799397700b
I20260812 06:16:34.556684 13893 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:34.571182 13893 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:34.571673 13893 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:34.578773 13893 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab: Generated new TSK 0
I20260812 06:16:34.578958 13893 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:34.587308 13425 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:34.589296 13911 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:16:34.589437 13909 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:16:34.589556 13425 server_base.cc:1061] running on GCE node
W20260812 06:16:34.589609 13914 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:16:34.589826 13425 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:34.589874 13425 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:16:34.589891 13425 hybrid_clock.cc:648] HybridClock initialized: now 1786515394589891 us; error 0 us; skew 500 ppm
I20260812 06:16:34.590699 13425 webserver.cc:533] Webserver started at http://127.13.28.65:42981/ using document root <none> and password file <none>
I20260812 06:16:34.590880 13425 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:34.590940 13425 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:34.590994 13425 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:34.591343 13425 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/instance:
uuid: "b1ce7b82814c4da3a934f42fa735b377"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-znh6"
I20260812 06:16:34.592834 13425 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:34.593716 13927 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:16:34.593941 13425 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:34.594004 13425 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root
uuid: "b1ce7b82814c4da3a934f42fa735b377"
format_stamp: "Formatted at 2026-08-12 06:16:34 on dist-test-slave-znh6"
I20260812 06:16:34.594056 13425 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-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:16:34.606981 13425 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:34.607296 13425 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:34.607553 13425 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:34.608021 13425 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:34.608059 13425 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.608119 13425 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:34.608160 13425 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:34.612583 13425 rpc_server.cc:307] RPC server started. Bound to: 127.13.28.65:34391
I20260812 06:16:34.612623 14048 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.13.28.65:34391 every 8 connection(s)
I20260812 06:16:34.620700 14049 heartbeater.cc:344] Connected to a master server at 127.13.28.126:41701
I20260812 06:16:34.620792 14049 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:34.621013 14049 heartbeater.cc:507] Master 127.13.28.126:41701 requested a full tablet report, sending...
I20260812 06:16:34.621634 13814 ts_manager.cc:194] Registered new tserver with Master: b1ce7b82814c4da3a934f42fa735b377 (127.13.28.65:34391)
I20260812 06:16:34.621910 13425 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008882831s
I20260812 06:16:34.622447 13814 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46572
I20260812 06:16:34.628413 13814 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46588:
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:16:34.636781 13978 tablet_service.cc:1511] Processing CreateTablet for tablet 3cacbeb1f68444a088c49721370398c0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=28f451b1e9ac451ebbe7fa6fdbdad3bd]), partition=
I20260812 06:16:34.637081 13978 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 3cacbeb1f68444a088c49721370398c0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:34.638947 14062 tablet_bootstrap.cc:492] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Bootstrap starting.
I20260812 06:16:34.639925 14062 tablet_bootstrap.cc:654] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:34.640962 14062 tablet_bootstrap.cc:492] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: No bootstrap required, opened a new log
I20260812 06:16:34.641057 14062 ts_tablet_manager.cc:1403] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Time spent bootstrapping tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:16:34.641465 14062 raft_consensus.cc:359] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1ce7b82814c4da3a934f42fa735b377" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 34391 } }
I20260812 06:16:34.641551 14062 raft_consensus.cc:385] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:34.641613 14062 raft_consensus.cc:740] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b1ce7b82814c4da3a934f42fa735b377, State: Initialized, Role: FOLLOWER
I20260812 06:16:34.641775 14062 consensus_queue.cc:260] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [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: "b1ce7b82814c4da3a934f42fa735b377" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 34391 } }
I20260812 06:16:34.641847 14062 raft_consensus.cc:399] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:34.641907 14062 raft_consensus.cc:493] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:34.641969 14062 raft_consensus.cc:3060] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:34.642984 14062 raft_consensus.cc:515] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1ce7b82814c4da3a934f42fa735b377" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 34391 } }
I20260812 06:16:34.643131 14062 leader_election.cc:304] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [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: b1ce7b82814c4da3a934f42fa735b377; no voters: 
I20260812 06:16:34.643335 14062 leader_election.cc:290] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:34.643446 14066 raft_consensus.cc:2804] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:34.643640 14066 raft_consensus.cc:697] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 1 LEADER]: Becoming Leader. State: Replica: b1ce7b82814c4da3a934f42fa735b377, State: Running, Role: LEADER
I20260812 06:16:34.643769 14066 consensus_queue.cc:237] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [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: "b1ce7b82814c4da3a934f42fa735b377" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 34391 } }
I20260812 06:16:34.643810 14049 heartbeater.cc:499] Master 127.13.28.126:41701 was elected leader, sending a full tablet report...
I20260812 06:16:34.643788 14062 ts_tablet_manager.cc:1434] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:16:34.645113 13814 catalog_manager.cc:5719] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 reported cstate change: term changed from 0 to 1, leader changed from <none> to b1ce7b82814c4da3a934f42fa735b377 (127.13.28.65). New cstate: current_term: 1 leader_uuid: "b1ce7b82814c4da3a934f42fa735b377" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b1ce7b82814c4da3a934f42fa735b377" member_type: VOTER last_known_addr { host: "127.13.28.65" port: 34391 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:34.703069 13425 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.014s	sys 0.007s
I20260812 06:16:34.863476 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushMRSOp(3cacbeb1f68444a088c49721370398c0): perf score=19.054940
I20260812 06:16:35.016431 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushMRSOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.153s	user 0.107s	sys 0.044s Metrics: {"bytes_written":11897251,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":803,"drs_written":1,"lbm_read_time_us":92,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40280,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1450}
I20260812 06:16:35.017107 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling LogGCOp(3cacbeb1f68444a088c49721370398c0): free 20290830 bytes of WAL
I20260812 06:16:35.017365 13937 log_reader.cc:385] T 3cacbeb1f68444a088c49721370398c0: removed 2 log segments from log reader
I20260812 06:16:35.017413 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000001 (ops 1-6)
I20260812 06:16:35.017444 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000002 (ops 7-10)
I20260812 06:16:35.021590 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: LogGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:16:35.021955 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.041934 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.020s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.042419 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0): 16821646 bytes on disk
I20260812 06:16:35.042863 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:16:35.043280 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:35.184507 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.141s	user 0.118s	sys 0.023s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20303033,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":551,"lbm_read_time_us":10443,"lbm_reads_lt_1ms":450,"lbm_write_time_us":25405,"lbm_writes_lt_1ms":433,"mutex_wait_us":21,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":5888,"thread_start_us":328,"threads_started":5,"update_count":1950}
I20260812 06:16:35.185163 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:35.222260 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.035s	user 0.011s	sys 0.017s Metrics: {"bytes_written":12389538,"delete_count":0,"lbm_write_time_us":13743,"lbm_writes_lt_1ms":305,"reinsert_count":0,"update_count":1510}
I20260812 06:16:35.222702 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.233722 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4020609,"delete_count":0,"lbm_write_time_us":3929,"lbm_writes_lt_1ms":101,"reinsert_count":0,"update_count":490}
I20260812 06:16:35.234172 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:35.366123 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.132s	user 0.091s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":527,"lbm_read_time_us":10241,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24950,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:16:35.366744 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:35.412739 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.046s	user 0.024s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15783,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.413223 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.423800 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.424185 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:35.572217 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.148s	user 0.102s	sys 0.046s 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":164,"lbm_read_time_us":10638,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24031,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:16:35.572870 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:35.612272 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15927,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.612715 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.624325 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.624751 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:35.752835 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.128s	user 0.110s	sys 0.017s 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":152,"lbm_read_time_us":10047,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24621,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:16:35.753539 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:35.791356 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.037s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15188,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.791813 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.802337 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.803033 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:35.928938 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.126s	user 0.104s	sys 0.020s 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":1096,"lbm_read_time_us":8861,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25203,"lbm_writes_lt_1ms":443,"mutex_wait_us":752,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":24320,"update_count":2000}
I20260812 06:16:35.929617 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:35.974731 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.045s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14993,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:35.975281 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:35.989974 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6054,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:35.990404 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:36.143440 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.153s	user 0.103s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713270,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1144,"lbm_read_time_us":11679,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23348,"lbm_writes_lt_1ms":443,"mutex_wait_us":369,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:16:36.144140 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:36.185763 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.041s	user 0.016s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17112,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":1500}
I20260812 06:16:36.186280 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:36.196964 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4144,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.197714 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:36.322499 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.124s	user 0.104s	sys 0.020s 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":751,"lbm_read_time_us":9264,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24283,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11136,"update_count":2000}
I20260812 06:16:36.323055 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:36.369304 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.046s	user 0.021s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14083,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:36.369820 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:36.380977 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.381453 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushMRSOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:36.415169 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushMRSOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.034s	user 0.028s	sys 0.005s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":270,"dirs.run_wall_time_us":1375,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1788,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:36.415747 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling LogGCOp(3cacbeb1f68444a088c49721370398c0): free 133477417 bytes of WAL
I20260812 06:16:36.415972 13937 log_reader.cc:385] T 3cacbeb1f68444a088c49721370398c0: removed 13 log segments from log reader
I20260812 06:16:36.416033 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000003 (ops 11-15)
I20260812 06:16:36.416087 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000004 (ops 16-20)
I20260812 06:16:36.416146 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000005 (ops 21-25)
I20260812 06:16:36.416188 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000006 (ops 26-30)
I20260812 06:16:36.416224 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000007 (ops 31-35)
I20260812 06:16:36.416257 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000008 (ops 36-40)
I20260812 06:16:36.416293 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000009 (ops 41-45)
I20260812 06:16:36.416330 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000010 (ops 46-50)
I20260812 06:16:36.416368 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000011 (ops 51-55)
I20260812 06:16:36.416412 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000012 (ops 56-60)
I20260812 06:16:36.416448 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000013 (ops 61-65)
I20260812 06:16:36.416486 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000014 (ops 66-70)
I20260812 06:16:36.416522 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000015 (ops 71-75)
I20260812 06:16:36.448812 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: LogGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:16:36.449293 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=4.173312
I20260812 06:16:36.467813 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":6030801,"delete_count":0,"lbm_write_time_us":7643,"lbm_writes_lt_1ms":150,"reinsert_count":0,"update_count":735}
I20260812 06:16:36.468292 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=1.196750
I20260812 06:16:36.476897 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.008s	user 0.006s	sys 0.000s Metrics: {"bytes_written":2174479,"delete_count":0,"lbm_write_time_us":2500,"lbm_writes_lt_1ms":56,"reinsert_count":0,"update_count":265}
I20260812 06:16:36.477393 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:36.650231 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.173s	user 0.115s	sys 0.057s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918290,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":773,"lbm_read_time_us":13262,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34761,"lbm_writes_lt_1ms":643,"mutex_wait_us":25,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:16:36.650942 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:36.700254 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.049s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21535,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:36.700990 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0): 483 bytes on disk
I20260812 06:16:36.701553 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":100,"lbm_reads_lt_1ms":4}
I20260812 06:16:36.701996 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:36.717861 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6251,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:36.718514 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:36.886018 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.167s	user 0.131s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":189,"lbm_read_time_us":10504,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31916,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2500}
I20260812 06:16:36.886713 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:36.940546 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.054s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24099,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:36.941005 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:37.084172 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.143s	user 0.097s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1239,"lbm_read_time_us":8619,"lbm_reads_lt_1ms":467,"lbm_write_time_us":23908,"lbm_writes_lt_1ms":443,"mutex_wait_us":380,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:16:37.084764 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:37.138551 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.054s	user 0.021s	sys 0.028s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":26307,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:37.139091 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:37.150509 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4326,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:37.151039 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:37.359421 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.208s	user 0.133s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":13075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32560,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16384,"update_count":2500}
I20260812 06:16:37.360172 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=15.087375
I20260812 06:16:37.408849 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.048s	user 0.023s	sys 0.024s Metrics: {"bytes_written":16820141,"delete_count":0,"lbm_write_time_us":21856,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:37.409343 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:37.425671 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.016s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":500}
I20260812 06:16:37.426148 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:37.446116 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.020s	user 0.010s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:37.446635 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:37.647058 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.200s	user 0.131s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918200,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":458,"lbm_read_time_us":14542,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33680,"lbm_writes_lt_1ms":643,"mutex_wait_us":80,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":28288,"update_count":3000}
I20260812 06:16:37.647769 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:37.707769 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.059s	user 0.025s	sys 0.033s Metrics: {"bytes_written":16532978,"delete_count":0,"lbm_write_time_us":20233,"lbm_writes_lt_1ms":406,"mutex_wait_us":130,"reinsert_count":0,"update_count":2015}
I20260812 06:16:37.708266 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:37.719193 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":4287,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:16:37.719621 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushMRSOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:37.750391 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushMRSOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":183,"dirs.run_cpu_time_us":212,"dirs.run_wall_time_us":1264,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1892,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":768}
I20260812 06:16:37.751096 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling LogGCOp(3cacbeb1f68444a088c49721370398c0): free 112239274 bytes of WAL
I20260812 06:16:37.751343 13937 log_reader.cc:385] T 3cacbeb1f68444a088c49721370398c0: removed 11 log segments from log reader
I20260812 06:16:37.751415 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000016 (ops 76-80)
I20260812 06:16:37.751462 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000017 (ops 81-85)
I20260812 06:16:37.751523 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000018 (ops 86-90)
I20260812 06:16:37.751567 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000019 (ops 91-94)
I20260812 06:16:37.751606 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000020 (ops 95-99)
I20260812 06:16:37.751645 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000021 (ops 100-104)
I20260812 06:16:37.751684 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000022 (ops 105-109)
I20260812 06:16:37.751722 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000023 (ops 110-114)
I20260812 06:16:37.751761 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000024 (ops 115-119)
I20260812 06:16:37.751799 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000025 (ops 120-124)
I20260812 06:16:37.751837 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000026 (ops 125-129)
I20260812 06:16:37.778366 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: LogGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.027s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:37.778808 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=4.173312
I20260812 06:16:37.792439 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":5620561,"delete_count":0,"lbm_write_time_us":5508,"lbm_writes_lt_1ms":140,"reinsert_count":0,"update_count":685}
I20260812 06:16:37.792887 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=1.196750
I20260812 06:16:37.800935 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.008s	user 0.002s	sys 0.004s Metrics: {"bytes_written":2584729,"delete_count":0,"lbm_write_time_us":2613,"lbm_writes_lt_1ms":66,"reinsert_count":0,"update_count":315}
I20260812 06:16:37.801677 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:38.040968 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.239s	user 0.157s	sys 0.068s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020713,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":216,"lbm_read_time_us":15549,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41119,"lbm_writes_lt_1ms":743,"mutex_wait_us":61,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:16:38.041693 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=18.063937
I20260812 06:16:38.108305 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.066s	user 0.046s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":28702,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:38.108829 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:38.118775 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102660,"delete_count":0,"lbm_write_time_us":3889,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.119494 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:38.322293 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.202s	user 0.160s	sys 0.042s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918099,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":322,"lbm_read_time_us":14603,"lbm_reads_lt_1ms":672,"lbm_write_time_us":37326,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25984,"update_count":3000}
I20260812 06:16:38.323179 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0): 447 bytes on disk
I20260812 06:16:38.323786 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:16:38.324412 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:38.365377 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.041s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.365869 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:38.377467 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4337,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.378013 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:38.542160 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.164s	user 0.112s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":12203,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29192,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:16:38.542776 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:38.595162 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.052s	user 0.039s	sys 0.013s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23156,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.595755 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:38.751442 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.155s	user 0.098s	sys 0.047s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":792,"lbm_read_time_us":11002,"lbm_reads_lt_1ms":467,"lbm_write_time_us":24579,"lbm_writes_lt_1ms":443,"mutex_wait_us":80,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7552,"update_count":2000}
I20260812 06:16:38.752303 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:38.805933 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.053s	user 0.036s	sys 0.014s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":23564,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:38.806452 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:38.819370 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.013s	user 0.001s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:38.819847 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:39.013960 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.194s	user 0.141s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":383,"lbm_read_time_us":12125,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31848,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34048,"update_count":2500}
I20260812 06:16:39.014631 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:39.065646 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.051s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":21956,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.066179 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:39.077898 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.078614 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:39.243425 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.165s	user 0.115s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":346,"lbm_read_time_us":9844,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30636,"lbm_writes_lt_1ms":543,"mutex_wait_us":62,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2500}
I20260812 06:16:39.244140 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=14.095187
I20260812 06:16:39.292646 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.048s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22360,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.293185 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=2.188937
I20260812 06:16:39.304761 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4346,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.305255 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushMRSOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:39.333217 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushMRSOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":224,"dirs.run_wall_time_us":1403,"drs_written":1,"lbm_read_time_us":118,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1850,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:39.333849 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling LogGCOp(3cacbeb1f68444a088c49721370398c0): free 129320848 bytes of WAL
I20260812 06:16:39.334090 13937 log_reader.cc:385] T 3cacbeb1f68444a088c49721370398c0: removed 13 log segments from log reader
I20260812 06:16:39.334136 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000027 (ops 130-134)
I20260812 06:16:39.334165 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000028 (ops 135-139)
I20260812 06:16:39.334227 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000029 (ops 140-144)
I20260812 06:16:39.334260 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000030 (ops 145-148)
I20260812 06:16:39.334301 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000031 (ops 149-153)
I20260812 06:16:39.334359 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000032 (ops 154-158)
I20260812 06:16:39.334396 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000033 (ops 159-163)
I20260812 06:16:39.334456 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000034 (ops 164-168)
I20260812 06:16:39.334497 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000035 (ops 169-172)
I20260812 06:16:39.334538 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000036 (ops 173-177)
I20260812 06:16:39.334578 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000037 (ops 178-182)
I20260812 06:16:39.334617 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000038 (ops 183-187)
I20260812 06:16:39.334657 13937 log.cc:1079] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: Deleting log segment in path: /tmp/dist-test-taskEVzj0G/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515389140096-13425-0/minicluster-data/ts-0-root/wals/3cacbeb1f68444a088c49721370398c0/wal-000000039 (ops 188-192)
I20260812 06:16:39.362922 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: LogGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.029s	user 0.002s	sys 0.027s Metrics: {}
I20260812 06:16:39.363421 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=4.173312
I20260812 06:16:39.388780 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.025s	user 0.008s	sys 0.015s Metrics: {"bytes_written":6112848,"delete_count":0,"lbm_write_time_us":6151,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:16:39.389248 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:39.395715 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.006s	user 0.005s	sys 0.000s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2069,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:16:39.396193 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0): 483 bytes on disk
I20260812 06:16:39.396595 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: UndoDeltaBlockGCOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:39.397127 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0): perf score=1.000000
I20260812 06:16:39.540608 13425 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.837s	user 1.746s	sys 0.186s
I20260812 06:16:39.614717 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: MajorDeltaCompactionOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.217s	user 0.128s	sys 0.087s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020699,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":15570,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39901,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3500}
I20260812 06:16:39.615250 14050 maintenance_manager.cc:419] P b1ce7b82814c4da3a934f42fa735b377: Scheduling FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0): perf score=10.126437
I20260812 06:16:39.639840 13425 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.099s	user 0.003s	sys 0.000s
I20260812 06:16:39.640470 13425 tablet_server.cc:179] TabletServer@127.13.28.65:0 shutting down...
I20260812 06:16:39.655508 13937 maintenance_manager.cc:643] P b1ce7b82814c4da3a934f42fa735b377: FlushDeltaMemStoresOp(3cacbeb1f68444a088c49721370398c0) complete. Timing: real 0.040s	user 0.032s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17364,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.655978 13425 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:39.656184 13425 tablet_replica.cc:333] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377: stopping tablet replica
I20260812 06:16:39.656342 13425 raft_consensus.cc:2243] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:39.671924 13425 raft_consensus.cc:2272] T 3cacbeb1f68444a088c49721370398c0 P b1ce7b82814c4da3a934f42fa735b377 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:39.675285 13425 tablet_server.cc:196] TabletServer@127.13.28.65:0 shutdown complete.
I20260812 06:16:39.677965 13425 master.cc:562] Master@127.13.28.126:41701 shutting down...
I20260812 06:16:39.681180 13425 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:39.681329 13425 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:39.681414 13425 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1a41d396b38b400a9b96c3b82250efab: stopping tablet replica
I20260812 06:16:39.693446 13425 master.cc:584] Master@127.13.28.126:41701 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5284 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10632 ms total)

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