[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:53.165799 28075 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.106.254:42577
I20260812 06:18:53.166754 28075 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:53.167344 28075 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.173724 28085 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.173692 28088 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.173787 28075 server_base.cc:1061] running on GCE node
W20260812 06:18:53.174009 28090 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.174490 28075 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.174604 28075 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.174666 28075 hybrid_clock.cc:648] HybridClock initialized: now 1786515533174663 us; error 0 us; skew 500 ppm
I20260812 06:18:53.176244 28075 webserver.cc:533] Webserver started at http://127.27.106.254:44703/ using document root <none> and password file <none>
I20260812 06:18:53.176749 28075 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.176838 28075 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.177076 28075 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.178673 28075 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/master-0-root/instance:
uuid: "07d763f6c72f4bea8c755d18b62f7ac2"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-8hhm"
I20260812 06:18:53.181979 28075 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:18:53.183830 28097 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.184780 28075 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:53.184911 28075 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/master-0-root
uuid: "07d763f6c72f4bea8c755d18b62f7ac2"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-8hhm"
I20260812 06:18:53.185014 28075 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:53.216434 28075 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:53.217151 28075 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:53.217386 28075 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:53.225479 28075 rpc_server.cc:307] RPC server started. Bound to: 127.27.106.254:42577
I20260812 06:18:53.225497 28199 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.106.254:42577 every 8 connection(s)
I20260812 06:18:53.227656 28204 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:53.232911 28204 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: Bootstrap starting.
I20260812 06:18:53.235210 28204 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:53.236081 28204 log.cc:826] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:53.237761 28204 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: No bootstrap required, opened a new log
I20260812 06:18:53.240335 28204 raft_consensus.cc:359] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER }
I20260812 06:18:53.240490 28204 raft_consensus.cc:385] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:53.240567 28204 raft_consensus.cc:740] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 07d763f6c72f4bea8c755d18b62f7ac2, State: Initialized, Role: FOLLOWER
I20260812 06:18:53.241154 28204 consensus_queue.cc:260] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [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: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER }
I20260812 06:18:53.241369 28204 raft_consensus.cc:399] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:53.241446 28204 raft_consensus.cc:493] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:53.241604 28204 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:53.242348 28204 raft_consensus.cc:515] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER }
I20260812 06:18:53.242762 28204 leader_election.cc:304] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [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: 07d763f6c72f4bea8c755d18b62f7ac2; no voters: 
I20260812 06:18:53.243089 28204 leader_election.cc:290] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:53.243220 28209 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:53.243500 28209 raft_consensus.cc:697] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 1 LEADER]: Becoming Leader. State: Replica: 07d763f6c72f4bea8c755d18b62f7ac2, State: Running, Role: LEADER
I20260812 06:18:53.243964 28209 consensus_queue.cc:237] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [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: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER }
I20260812 06:18:53.244059 28204 sys_catalog.cc:565] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:53.246081 28212 sys_catalog.cc:455] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER } }
I20260812 06:18:53.246227 28212 sys_catalog.cc:458] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.246315 28075 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:53.246057 28214 sys_catalog.cc:455] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 07d763f6c72f4bea8c755d18b62f7ac2. Latest consensus state: current_term: 1 leader_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "07d763f6c72f4bea8c755d18b62f7ac2" member_type: VOTER } }
I20260812 06:18:53.246428 28214 sys_catalog.cc:458] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.246672 28248 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:53.248719 28248 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:53.253355 28248 catalog_manager.cc:1383] Generated new cluster ID: c2273e1804ea486792d5c1bba5b08836
I20260812 06:18:53.253417 28248 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:53.264963 28248 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:53.266109 28248 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:53.274653 28248 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: Generated new TSK 0
I20260812 06:18:53.275267 28248 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:53.278702 28075 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.281167 28268 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.281177 28260 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.281412 28263 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.281977 28075 server_base.cc:1061] running on GCE node
I20260812 06:18:53.282150 28075 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.282197 28075 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.282213 28075 hybrid_clock.cc:648] HybridClock initialized: now 1786515533282213 us; error 0 us; skew 500 ppm
I20260812 06:18:53.283129 28075 webserver.cc:533] Webserver started at http://127.27.106.193:45943/ using document root <none> and password file <none>
I20260812 06:18:53.283308 28075 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.283363 28075 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.283456 28075 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.283842 28075 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/instance:
uuid: "919e9bd907ab46b6a92581aa4e5e2b38"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-8hhm"
I20260812 06:18:53.285356 28075 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:53.286369 28290 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.286614 28075 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:53.286685 28075 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root
uuid: "919e9bd907ab46b6a92581aa4e5e2b38"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-8hhm"
I20260812 06:18:53.286767 28075 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:53.294443 28075 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:53.294878 28075 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:53.295396 28075 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:53.296265 28075 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:53.296319 28075 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.296384 28075 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:53.296427 28075 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.303607 28075 rpc_server.cc:307] RPC server started. Bound to: 127.27.106.193:42109
I20260812 06:18:53.303640 28409 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.106.193:42109 every 8 connection(s)
I20260812 06:18:53.313825 28412 heartbeater.cc:344] Connected to a master server at 127.27.106.254:42577
I20260812 06:18:53.314085 28412 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:53.314576 28412 heartbeater.cc:507] Master 127.27.106.254:42577 requested a full tablet report, sending...
I20260812 06:18:53.316133 28130 ts_manager.cc:194] Registered new tserver with Master: 919e9bd907ab46b6a92581aa4e5e2b38 (127.27.106.193:42109)
I20260812 06:18:53.316509 28075 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.012262683s
I20260812 06:18:53.317752 28130 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:51700
I20260812 06:18:53.327219 28130 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:51716:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:53.341537 28347 tablet_service.cc:1511] Processing CreateTablet for tablet a5fd605bec5c46d3b1b819f195f9f2e5 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7c31bcb8430a4c30812062e677809fa7]), partition=
I20260812 06:18:53.341974 28347 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a5fd605bec5c46d3b1b819f195f9f2e5. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:53.344357 28435 tablet_bootstrap.cc:492] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Bootstrap starting.
I20260812 06:18:53.345419 28435 tablet_bootstrap.cc:654] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:53.346743 28435 tablet_bootstrap.cc:492] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: No bootstrap required, opened a new log
I20260812 06:18:53.346846 28435 ts_tablet_manager.cc:1403] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:18:53.347245 28435 raft_consensus.cc:359] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "919e9bd907ab46b6a92581aa4e5e2b38" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 42109 } }
I20260812 06:18:53.347352 28435 raft_consensus.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:53.347374 28435 raft_consensus.cc:740] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 919e9bd907ab46b6a92581aa4e5e2b38, State: Initialized, Role: FOLLOWER
I20260812 06:18:53.347554 28435 consensus_queue.cc:260] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [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: "919e9bd907ab46b6a92581aa4e5e2b38" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 42109 } }
I20260812 06:18:53.347640 28435 raft_consensus.cc:399] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:53.347695 28435 raft_consensus.cc:493] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:53.347747 28435 raft_consensus.cc:3060] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:53.348439 28435 raft_consensus.cc:515] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "919e9bd907ab46b6a92581aa4e5e2b38" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 42109 } }
I20260812 06:18:53.348580 28435 leader_election.cc:304] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [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: 919e9bd907ab46b6a92581aa4e5e2b38; no voters: 
I20260812 06:18:53.348810 28435 leader_election.cc:290] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:53.348939 28439 raft_consensus.cc:2804] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:53.349133 28435 ts_tablet_manager.cc:1434] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:53.349368 28412 heartbeater.cc:499] Master 127.27.106.254:42577 was elected leader, sending a full tablet report...
I20260812 06:18:53.349196 28439 raft_consensus.cc:697] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 1 LEADER]: Becoming Leader. State: Replica: 919e9bd907ab46b6a92581aa4e5e2b38, State: Running, Role: LEADER
I20260812 06:18:53.349782 28439 consensus_queue.cc:237] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [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: "919e9bd907ab46b6a92581aa4e5e2b38" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 42109 } }
I20260812 06:18:53.352135 28130 catalog_manager.cc:5719] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 reported cstate change: term changed from 0 to 1, leader changed from <none> to 919e9bd907ab46b6a92581aa4e5e2b38 (127.27.106.193). New cstate: current_term: 1 leader_uuid: "919e9bd907ab46b6a92581aa4e5e2b38" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "919e9bd907ab46b6a92581aa4e5e2b38" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 42109 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:53.419082 28075 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.062s	user 0.027s	sys 0.006s
I20260812 06:18:53.554847 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=15.086190
I20260812 06:18:53.754508 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.199s	user 0.148s	sys 0.048s Metrics: {"bytes_written":15999661,"cfile_init":1,"compiler_manager_pool.queue_time_us":221,"delete_count":0,"dirs.queue_time_us":841,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":2313,"drs_written":1,"lbm_read_time_us":94,"lbm_reads_lt_1ms":4,"lbm_write_time_us":55064,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":190,"threads_started":1,"update_count":1950}
I20260812 06:18:53.755954 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 20743880 bytes of WAL
I20260812 06:18:53.756258 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 2 log segments from log reader
I20260812 06:18:53.756331 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000001 (ops 1-6)
I20260812 06:18:53.756394 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000002 (ops 7-11)
I20260812 06:18:53.762362 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.006s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:53.762768 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): 12719229 bytes on disk
I20260812 06:18:53.763480 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:18:53.763882 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=3.181125
I20260812 06:18:53.790506 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.026s	user 0.008s	sys 0.009s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":7246,"lbm_writes_lt_1ms":113,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":550}
I20260812 06:18:53.791055 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:53.805698 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.014s	user 0.005s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5780,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:53.806181 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:54.023562 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.217s	user 0.128s	sys 0.082s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28466969,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":950,"lbm_read_time_us":15899,"lbm_reads_lt_1ms":659,"lbm_write_time_us":38035,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":374,"threads_started":5,"update_count":2950}
I20260812 06:18:54.024303 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=14.095187
I20260812 06:18:54.097922 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.073s	user 0.026s	sys 0.046s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":29997,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:54.098486 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:54.110181 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4582,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.110637 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:54.306772 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.196s	user 0.134s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":769,"lbm_read_time_us":15443,"lbm_reads_lt_1ms":572,"lbm_write_time_us":35666,"lbm_writes_lt_1ms":543,"mutex_wait_us":343,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:54.307475 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:54.349423 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.042s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18591,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.349913 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:54.361155 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.361668 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:54.494159 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.132s	user 0.102s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":318,"lbm_read_time_us":11507,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25291,"lbm_writes_lt_1ms":443,"mutex_wait_us":117,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:18:54.494779 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:54.541631 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.047s	user 0.019s	sys 0.019s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":17829,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.542079 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:54.553392 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4424,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.554147 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:54.686398 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.132s	user 0.108s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672280,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":320,"lbm_read_time_us":11622,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26308,"lbm_writes_lt_1ms":443,"mutex_wait_us":115,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:54.686975 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:54.723163 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.036s	user 0.022s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16013,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.723690 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:54.739238 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.015s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6015,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.739768 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:54.877825 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.138s	user 0.117s	sys 0.019s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":356,"lbm_read_time_us":11273,"lbm_reads_lt_1ms":472,"lbm_write_time_us":28662,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2000}
I20260812 06:18:54.878479 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:54.933049 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.054s	user 0.021s	sys 0.023s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17486,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.933643 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:54.945670 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.012s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.946218 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:55.111479 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.165s	user 0.097s	sys 0.068s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":13165,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27717,"lbm_writes_lt_1ms":443,"mutex_wait_us":30,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:18:55.112169 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:55.152453 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.040s	user 0.025s	sys 0.011s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16880,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.152972 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:55.166018 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.013s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5081,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.166733 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:55.202126 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.035s	user 0.033s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":251,"dirs.run_wall_time_us":1544,"drs_written":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2041,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":384}
I20260812 06:18:55.203056 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 120553380 bytes of WAL
I20260812 06:18:55.203378 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 12 log segments from log reader
I20260812 06:18:55.203454 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000003 (ops 12-16)
I20260812 06:18:55.203498 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000004 (ops 17-21)
I20260812 06:18:55.203533 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000005 (ops 22-26)
I20260812 06:18:55.203557 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000006 (ops 27-30)
I20260812 06:18:55.203606 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000007 (ops 31-35)
I20260812 06:18:55.203658 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000008 (ops 36-40)
I20260812 06:18:55.203693 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000009 (ops 41-45)
I20260812 06:18:55.203742 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000010 (ops 46-50)
I20260812 06:18:55.203776 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000011 (ops 51-54)
I20260812 06:18:55.203819 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000012 (ops 55-59)
I20260812 06:18:55.203861 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000013 (ops 60-64)
I20260812 06:18:55.203902 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000014 (ops 65-69)
I20260812 06:18:55.237138 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.034s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:18:55.237774 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): 482 bytes on disk
I20260812 06:18:55.238298 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.238829 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=5.165500
I20260812 06:18:55.268496 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.029s	user 0.013s	sys 0.013s Metrics: {"bytes_written":6892306,"delete_count":0,"lbm_write_time_us":8612,"lbm_writes_lt_1ms":171,"reinsert_count":0,"update_count":840}
I20260812 06:18:55.269312 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:55.280277 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.005s	sys 0.001s Metrics: {"bytes_written":1312952,"delete_count":0,"lbm_write_time_us":2450,"lbm_writes_lt_1ms":35,"reinsert_count":0,"update_count":160}
I20260812 06:18:55.280692 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 12017932 bytes of WAL
I20260812 06:18:55.280900 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 1 log segments from log reader
I20260812 06:18:55.280944 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000015 (ops 70-74)
I20260812 06:18:55.283491 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:55.283789 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:55.498981 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.215s	user 0.127s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877275,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":277,"lbm_read_time_us":15474,"lbm_reads_lt_1ms":670,"lbm_write_time_us":39944,"lbm_writes_lt_1ms":643,"mutex_wait_us":100,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":78,"threads_started":1,"update_count":3000}
I20260812 06:18:55.499617 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=14.095187
I20260812 06:18:55.559949 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.060s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21754,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:55.560510 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:55.571408 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.002s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.571874 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:55.753235 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.181s	user 0.122s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":712,"lbm_read_time_us":14543,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33059,"lbm_writes_lt_1ms":543,"mutex_wait_us":359,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:55.753880 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:55.796649 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.043s	user 0.014s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17966,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:55.797300 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:55.822082 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.023s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.822623 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:55.842662 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.020s	user 0.007s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3876,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:55.843171 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:56.029340 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.186s	user 0.114s	sys 0.069s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1433,"lbm_read_time_us":14119,"lbm_reads_lt_1ms":573,"lbm_write_time_us":34515,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:18:56.029907 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:56.074015 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.044s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18798,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.074532 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.085145 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4276,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.085611 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.095569 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.095954 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:56.288820 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.193s	user 0.130s	sys 0.047s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":533,"lbm_read_time_us":11404,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30859,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:18:56.289530 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=14.095187
I20260812 06:18:56.342099 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.052s	user 0.033s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":22109,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.342571 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.354488 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4561,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.355023 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:56.517035 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.162s	user 0.113s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":10558,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32567,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:18:56.517902 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:56.549862 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.032s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13069,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.550477 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.575961 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.025s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4869,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.576454 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.591508 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6213,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.592175 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:56.730707 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.138s	user 0.115s	sys 0.018s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":237,"lbm_read_time_us":9331,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27418,"lbm_writes_lt_1ms":543,"mutex_wait_us":30,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2500}
I20260812 06:18:56.731346 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:56.759542 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.028s	user 0.016s	sys 0.009s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":12190,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:56.760149 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.777797 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.017s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5773,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:56.778498 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:56.831241 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.053s	user 0.024s	sys 0.005s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1254,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2682,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:56.831991 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 117302595 bytes of WAL
I20260812 06:18:56.832266 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 12 log segments from log reader
I20260812 06:18:56.832340 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000016 (ops 75-79)
I20260812 06:18:56.832377 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000017 (ops 80-84)
I20260812 06:18:56.832412 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000018 (ops 85-89)
I20260812 06:18:56.832448 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000019 (ops 90-94)
I20260812 06:18:56.832482 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000020 (ops 95-98)
I20260812 06:18:56.832505 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000021 (ops 99-103)
I20260812 06:18:56.832528 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000022 (ops 104-108)
I20260812 06:18:56.832551 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000023 (ops 109-113)
I20260812 06:18:56.832581 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000024 (ops 114-118)
I20260812 06:18:56.832616 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000025 (ops 119-122)
I20260812 06:18:56.832649 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000026 (ops 123-127)
I20260812 06:18:56.832679 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000027 (ops 128-132)
I20260812 06:18:56.863590 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.031s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:18:56.864010 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=6.157687
I20260812 06:18:56.887599 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.023s	user 0.007s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":8967,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:56.888178 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 11564893 bytes of WAL
I20260812 06:18:56.888388 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 1 log segments from log reader
I20260812 06:18:56.888432 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000028 (ops 133-136)
I20260812 06:18:56.890828 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.002s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:56.891120 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): 483 bytes on disk
I20260812 06:18:56.891492 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:56.891952 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:56.903461 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4321,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.903891 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.157971 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.254s	user 0.171s	sys 0.076s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979741,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":622,"lbm_read_time_us":16989,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41711,"lbm_writes_lt_1ms":743,"mutex_wait_us":56,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":74,"threads_started":1,"update_count":3500}
I20260812 06:18:57.158710 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=18.063937
I20260812 06:18:57.250640 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.090s	user 0.050s	sys 0.033s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":33805,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.251283 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:57.263182 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4675,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.263706 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.463675 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.200s	user 0.144s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":138,"lbm_read_time_us":15720,"lbm_reads_lt_1ms":672,"lbm_write_time_us":33757,"lbm_writes_lt_1ms":643,"mutex_wait_us":31,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":17024,"update_count":3000}
I20260812 06:18:57.464658 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=14.095187
I20260812 06:18:57.522583 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.057s	user 0.042s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22475,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.523248 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.532884 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":2010381,"delete_count":0,"lbm_write_time_us":3500,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:18:57.533411 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.539614 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2219,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:18:57.540084 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.712114 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.172s	user 0.120s	sys 0.050s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774711,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":445,"lbm_read_time_us":13787,"lbm_reads_lt_1ms":573,"lbm_write_time_us":29665,"lbm_writes_lt_1ms":543,"mutex_wait_us":86,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:18:57.712607 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=14.095187
I20260812 06:18:57.769553 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.057s	user 0.032s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19883,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.770128 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:57.780876 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4131,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.781424 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:57.952672 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.171s	user 0.112s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":12628,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28516,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.953204 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:57.991559 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.038s	user 0.019s	sys 0.017s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16692,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:57.992161 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:58.013773 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.021s	user 0.007s	sys 0.014s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4493,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.014289 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:58.152230 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.138s	user 0.072s	sys 0.065s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1392,"lbm_read_time_us":8320,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23152,"lbm_writes_lt_1ms":443,"mutex_wait_us":334,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.152781 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=10.126437
I20260812 06:18:58.185401 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.032s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14066,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.186489 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:58.204582 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.205235 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:58.338498 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.133s	user 0.107s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":186,"lbm_read_time_us":7518,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24920,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8320,"update_count":2000}
I20260812 06:18:58.339015 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=11.118625
I20260812 06:18:58.385072 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.046s	user 0.023s	sys 0.019s Metrics: {"bytes_written":12717734,"delete_count":0,"lbm_write_time_us":18420,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:58.385619 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:58.419191 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.033s	user 0.005s	sys 0.010s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5318,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:58.419782 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:58.430784 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4431,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.431275 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:58.474615 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushMRSOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.043s	user 0.039s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":238,"dirs.run_wall_time_us":1311,"drs_written":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2344,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:58.475544 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 116849722 bytes of WAL
I20260812 06:18:58.475924 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 12 log segments from log reader
I20260812 06:18:58.475994 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000029 (ops 137-141)
I20260812 06:18:58.476049 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000030 (ops 142-146)
I20260812 06:18:58.476100 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000031 (ops 147-150)
I20260812 06:18:58.476148 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000032 (ops 151-155)
I20260812 06:18:58.476198 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000033 (ops 156-160)
I20260812 06:18:58.476248 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000034 (ops 161-164)
I20260812 06:18:58.476296 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000035 (ops 165-169)
I20260812 06:18:58.476343 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000036 (ops 170-174)
I20260812 06:18:58.476394 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000037 (ops 175-179)
I20260812 06:18:58.476442 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000038 (ops 180-184)
I20260812 06:18:58.476500 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000039 (ops 185-188)
I20260812 06:18:58.476549 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000040 (ops 189-193)
I20260812 06:18:58.513731 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.038s	user 0.000s	sys 0.037s Metrics: {}
I20260812 06:18:58.514428 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=6.157687
I20260812 06:18:58.560297 28075 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.141s	user 1.893s	sys 0.173s
I20260812 06:18:58.562255 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.048s	user 0.028s	sys 0.005s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":14572,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:58.562908 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): free 12018006 bytes of WAL
I20260812 06:18:58.563156 28304 log_reader.cc:385] T a5fd605bec5c46d3b1b819f195f9f2e5: removed 1 log segments from log reader
I20260812 06:18:58.563215 28304 log.cc:1079] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/a5fd605bec5c46d3b1b819f195f9f2e5/wal-000000041 (ops 194-198)
I20260812 06:18:58.566605 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: LogGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:58.567067 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5): 484 bytes on disk
I20260812 06:18:58.567574 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: UndoDeltaBlockGCOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":89,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.568332 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=2.188937
I20260812 06:18:58.586036 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: FlushDeltaMemStoresOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.018s	user 0.017s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.586596 28413 maintenance_manager.cc:419] P 919e9bd907ab46b6a92581aa4e5e2b38: Scheduling MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5): perf score=1.000000
I20260812 06:18:58.628796 28075 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.068s	user 0.002s	sys 0.000s
I20260812 06:18:58.629581 28075 tablet_server.cc:179] TabletServer@127.27.106.193:0 shutting down...
I20260812 06:18:58.791780 28304 maintenance_manager.cc:643] P 919e9bd907ab46b6a92581aa4e5e2b38: MajorDeltaCompactionOp(a5fd605bec5c46d3b1b819f195f9f2e5) complete. Timing: real 0.205s	user 0.164s	sys 0.040s Metrics: {"cfile_cache_hit":704,"cfile_cache_hit_bytes":28717352,"cfile_cache_miss":131,"cfile_cache_miss_bytes":8364920,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1287,"lbm_read_time_us":6456,"lbm_reads_lt_1ms":163,"lbm_write_time_us":46913,"lbm_writes_lt_1ms":843,"mutex_wait_us":692,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":14080,"thread_start_us":91,"threads_started":1,"update_count":4000}
I20260812 06:18:58.795279 28075 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:58.795805 28075 tablet_replica.cc:333] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38: stopping tablet replica
I20260812 06:18:58.796079 28075 raft_consensus.cc:2243] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:58.796344 28075 raft_consensus.cc:2272] T a5fd605bec5c46d3b1b819f195f9f2e5 P 919e9bd907ab46b6a92581aa4e5e2b38 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:58.812141 28075 tablet_server.cc:196] TabletServer@127.27.106.193:0 shutdown complete.
I20260812 06:18:58.866187 28075 master.cc:562] Master@127.27.106.254:42577 shutting down...
I20260812 06:18:58.870133 28075 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:58.870308 28075 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:58.870362 28075 tablet_replica.cc:333] T 00000000000000000000000000000000 P 07d763f6c72f4bea8c755d18b62f7ac2: stopping tablet replica
I20260812 06:18:58.884207 28075 master.cc:584] Master@127.27.106.254:42577 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5810 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:58.976238 28075 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.27.106.254:45893
I20260812 06:18:58.976584 28075 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:58.978672 28472 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:58.978677 28471 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.978693 28075 server_base.cc:1061] running on GCE node
W20260812 06:18:58.978725 28479 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:58.979051 28075 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:58.979097 28075 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:58.979113 28075 hybrid_clock.cc:648] HybridClock initialized: now 1786515538979113 us; error 0 us; skew 500 ppm
I20260812 06:18:58.979899 28075 webserver.cc:533] Webserver started at http://127.27.106.254:34141/ using document root <none> and password file <none>
I20260812 06:18:58.980022 28075 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:58.980059 28075 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:58.980123 28075 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:58.980454 28075 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/master-0-root/instance:
uuid: "79b9f4a4363141aa91dec4a97ae14880"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-8hhm"
I20260812 06:18:58.982592 28075 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:58.983441 28489 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:58.983661 28075 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:58.983750 28075 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/master-0-root
uuid: "79b9f4a4363141aa91dec4a97ae14880"
format_stamp: "Formatted at 2026-08-12 06:18:58 on dist-test-slave-8hhm"
I20260812 06:18:58.983835 28075 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.018850 28075 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.019299 28075 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.023648 28075 rpc_server.cc:307] RPC server started. Bound to: 127.27.106.254:45893
I20260812 06:18:59.026424 28595 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.026518 28591 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.106.254:45893 every 8 connection(s)
I20260812 06:18:59.032930 28595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880: Bootstrap starting.
I20260812 06:18:59.043942 28595 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.044997 28595 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880: No bootstrap required, opened a new log
I20260812 06:18:59.045398 28595 raft_consensus.cc:359] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER }
I20260812 06:18:59.045485 28595 raft_consensus.cc:385] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.045508 28595 raft_consensus.cc:740] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 79b9f4a4363141aa91dec4a97ae14880, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.045656 28595 consensus_queue.cc:260] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [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: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER }
I20260812 06:18:59.045744 28595 raft_consensus.cc:399] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.045770 28595 raft_consensus.cc:493] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.045801 28595 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.046456 28595 raft_consensus.cc:515] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER }
I20260812 06:18:59.046569 28595 leader_election.cc:304] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [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: 79b9f4a4363141aa91dec4a97ae14880; no voters: 
I20260812 06:18:59.046722 28595 leader_election.cc:290] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.046906 28600 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.047158 28600 raft_consensus.cc:697] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 1 LEADER]: Becoming Leader. State: Replica: 79b9f4a4363141aa91dec4a97ae14880, State: Running, Role: LEADER
I20260812 06:18:59.047204 28595 sys_catalog.cc:565] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:59.047318 28600 consensus_queue.cc:237] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [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: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER }
I20260812 06:18:59.047761 28609 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 79b9f4a4363141aa91dec4a97ae14880. Latest consensus state: current_term: 1 leader_uuid: "79b9f4a4363141aa91dec4a97ae14880" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER } }
I20260812 06:18:59.047747 28601 sys_catalog.cc:455] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "79b9f4a4363141aa91dec4a97ae14880" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "79b9f4a4363141aa91dec4a97ae14880" member_type: VOTER } }
I20260812 06:18:59.047861 28609 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.047870 28601 sys_catalog.cc:458] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.048200 28624 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:59.049158 28624 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:59.049402 28075 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:59.050928 28624 catalog_manager.cc:1383] Generated new cluster ID: e46f99549a8242bd800cc4c58230d0f0
I20260812 06:18:59.050989 28624 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:59.063153 28624 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:59.063766 28624 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:59.075838 28624 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880: Generated new TSK 0
I20260812 06:18:59.076047 28624 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:59.081887 28075 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.084227 28643 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.084362 28075 server_base.cc:1061] running on GCE node
W20260812 06:18:59.084295 28646 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.084542 28644 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.084785 28075 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.084839 28075 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:59.084888 28075 hybrid_clock.cc:648] HybridClock initialized: now 1786515539084887 us; error 0 us; skew 500 ppm
I20260812 06:18:59.085772 28075 webserver.cc:533] Webserver started at http://127.27.106.193:46265/ using document root <none> and password file <none>
I20260812 06:18:59.085958 28075 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.086032 28075 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.086112 28075 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.086488 28075 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/instance:
uuid: "cb0faf7f913c4137b16022e7e510ae61"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-8hhm"
I20260812 06:18:59.087981 28075 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:59.088925 28655 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.089172 28075 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.089288 28075 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root
uuid: "cb0faf7f913c4137b16022e7e510ae61"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-8hhm"
I20260812 06:18:59.089381 28075 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.119283 28075 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.119757 28075 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.120095 28075 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:59.120620 28075 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:59.120687 28075 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.120747 28075 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:59.120798 28075 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.125111 28075 rpc_server.cc:307] RPC server started. Bound to: 127.27.106.193:41109
I20260812 06:18:59.125185 28767 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.27.106.193:41109 every 8 connection(s)
I20260812 06:18:59.133538 28770 heartbeater.cc:344] Connected to a master server at 127.27.106.254:45893
I20260812 06:18:59.133661 28770 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:59.133878 28770 heartbeater.cc:507] Master 127.27.106.254:45893 requested a full tablet report, sending...
I20260812 06:18:59.134518 28522 ts_manager.cc:194] Registered new tserver with Master: cb0faf7f913c4137b16022e7e510ae61 (127.27.106.193:41109)
I20260812 06:18:59.135288 28522 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:39964
I20260812 06:18:59.135546 28075 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009930967s
I20260812 06:18:59.142267 28522 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:39966:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:59.152004 28703 tablet_service.cc:1511] Processing CreateTablet for tablet 0356a142f93347ea9a83bcb6f1787d85 (DEFAULT_TABLE table=heavy-update-compaction-test [id=f371f67a9534448ba032eda91658238d]), partition=
I20260812 06:18:59.152339 28703 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 0356a142f93347ea9a83bcb6f1787d85. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.154731 28800 tablet_bootstrap.cc:492] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Bootstrap starting.
I20260812 06:18:59.155586 28800 tablet_bootstrap.cc:654] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.156731 28800 tablet_bootstrap.cc:492] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: No bootstrap required, opened a new log
I20260812 06:18:59.156845 28800 ts_tablet_manager.cc:1403] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:59.157425 28800 raft_consensus.cc:359] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb0faf7f913c4137b16022e7e510ae61" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 41109 } }
I20260812 06:18:59.157548 28800 raft_consensus.cc:385] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.157596 28800 raft_consensus.cc:740] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: cb0faf7f913c4137b16022e7e510ae61, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.157737 28800 consensus_queue.cc:260] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [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: "cb0faf7f913c4137b16022e7e510ae61" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 41109 } }
I20260812 06:18:59.157831 28800 raft_consensus.cc:399] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.157878 28800 raft_consensus.cc:493] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.157933 28800 raft_consensus.cc:3060] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.158666 28800 raft_consensus.cc:515] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb0faf7f913c4137b16022e7e510ae61" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 41109 } }
I20260812 06:18:59.158821 28800 leader_election.cc:304] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [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: cb0faf7f913c4137b16022e7e510ae61; no voters: 
I20260812 06:18:59.159040 28800 leader_election.cc:290] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.159170 28806 raft_consensus.cc:2804] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.159396 28806 raft_consensus.cc:697] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 1 LEADER]: Becoming Leader. State: Replica: cb0faf7f913c4137b16022e7e510ae61, State: Running, Role: LEADER
I20260812 06:18:59.159409 28800 ts_tablet_manager.cc:1434] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:59.159453 28770 heartbeater.cc:499] Master 127.27.106.254:45893 was elected leader, sending a full tablet report...
I20260812 06:18:59.159600 28806 consensus_queue.cc:237] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [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: "cb0faf7f913c4137b16022e7e510ae61" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 41109 } }
I20260812 06:18:59.160959 28522 catalog_manager.cc:5719] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 reported cstate change: term changed from 0 to 1, leader changed from <none> to cb0faf7f913c4137b16022e7e510ae61 (127.27.106.193). New cstate: current_term: 1 leader_uuid: "cb0faf7f913c4137b16022e7e510ae61" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "cb0faf7f913c4137b16022e7e510ae61" member_type: VOTER last_known_addr { host: "127.27.106.193" port: 41109 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:59.222193 28075 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.014s	sys 0.009s
I20260812 06:18:59.376200 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85): perf score=19.054940
I20260812 06:18:59.531955 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.155s	user 0.096s	sys 0.054s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":37,"dirs.run_cpu_time_us":150,"dirs.run_wall_time_us":719,"drs_written":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41716,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:18:59.532523 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling LogGCOp(0356a142f93347ea9a83bcb6f1787d85): free 20743831 bytes of WAL
I20260812 06:18:59.532747 28664 log_reader.cc:385] T 0356a142f93347ea9a83bcb6f1787d85: removed 2 log segments from log reader
I20260812 06:18:59.532792 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000001 (ops 1-6)
I20260812 06:18:59.532821 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000002 (ops 7-11)
I20260812 06:18:59.537317 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: LogGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.005s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:59.537618 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:18:59.550055 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.012s	user 0.005s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4902,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.550546 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85): 16411392 bytes on disk
I20260812 06:18:59.550935 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.551297 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:18:59.699919 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.148s	user 0.117s	sys 0.031s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":292,"lbm_read_time_us":12201,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27521,"lbm_writes_lt_1ms":443,"mutex_wait_us":12,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":331,"threads_started":5,"update_count":2000}
I20260812 06:18:59.700521 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=10.126437
I20260812 06:18:59.742059 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.041s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":20092,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":1500}
I20260812 06:18:59.742604 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:18:59.758544 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5367,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.759184 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:18:59.902037 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.143s	user 0.103s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":2036,"lbm_read_time_us":9605,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25967,"lbm_writes_lt_1ms":443,"mutex_wait_us":389,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:18:59.902616 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:18:59.965939 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.063s	user 0.031s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20915,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.966531 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:18:59.983072 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.983500 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:00.171545 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.188s	user 0.116s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":14032,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34055,"lbm_writes_lt_1ms":543,"mutex_wait_us":42,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2500}
I20260812 06:19:00.172387 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:00.238986 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.066s	user 0.038s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22794,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.239499 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:00.250380 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4267,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.250789 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:00.445838 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.195s	user 0.117s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":779,"lbm_read_time_us":14236,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32947,"lbm_writes_lt_1ms":543,"mutex_wait_us":424,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:00.446378 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:00.496649 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.050s	user 0.030s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22177,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.497314 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:00.526894 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.029s	user 0.016s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6592,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.527555 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:00.751547 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.224s	user 0.148s	sys 0.075s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1718,"lbm_read_time_us":14871,"lbm_reads_lt_1ms":572,"lbm_write_time_us":36080,"lbm_writes_lt_1ms":543,"mutex_wait_us":452,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:00.752255 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:00.816064 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.064s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23757,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.816596 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:00.832046 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5840,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.832597 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:00.869884 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.037s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1807,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28,"spinlock_wait_cycles":30080}
I20260812 06:19:00.874236 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:00.891878 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.017s	user 0.011s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6869,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.892558 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling LogGCOp(0356a142f93347ea9a83bcb6f1787d85): free 115943225 bytes of WAL
I20260812 06:19:00.892895 28664 log_reader.cc:385] T 0356a142f93347ea9a83bcb6f1787d85: removed 11 log segments from log reader
I20260812 06:19:00.893013 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000003 (ops 12-16)
I20260812 06:19:00.893127 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000004 (ops 17-21)
I20260812 06:19:00.893265 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000005 (ops 22-26)
I20260812 06:19:00.893368 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000006 (ops 27-31)
I20260812 06:19:00.893479 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000007 (ops 32-36)
I20260812 06:19:00.893576 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000008 (ops 37-41)
I20260812 06:19:00.893671 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000009 (ops 42-46)
I20260812 06:19:00.893774 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000010 (ops 47-51)
I20260812 06:19:00.893868 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000011 (ops 52-56)
I20260812 06:19:00.893961 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000012 (ops 57-61)
I20260812 06:19:00.894098 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000013 (ops 62-66)
I20260812 06:19:00.928725 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: LogGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.036s	user 0.001s	sys 0.030s Metrics: {}
I20260812 06:19:00.929457 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85): 448 bytes on disk
I20260812 06:19:00.929977 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.930527 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:01.151520 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.221s	user 0.129s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877222,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":344,"lbm_read_time_us":18157,"lbm_reads_lt_1ms":665,"lbm_write_time_us":38257,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6656,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:01.152220 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=15.087375
I20260812 06:19:01.211994 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.059s	user 0.024s	sys 0.033s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22563,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:01.212484 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:01.226549 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.014s	user 0.008s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4866,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.226953 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:01.238126 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4262,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.238577 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:01.455704 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.217s	user 0.133s	sys 0.082s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":159,"lbm_read_time_us":17791,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33452,"lbm_writes_lt_1ms":643,"mutex_wait_us":23,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":3000}
I20260812 06:19:01.456368 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=15.087375
I20260812 06:19:01.502700 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.046s	user 0.018s	sys 0.027s Metrics: {"bytes_written":16820139,"delete_count":0,"lbm_write_time_us":20827,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:01.503497 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:01.519449 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5437,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.519961 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:01.720176 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.200s	user 0.118s	sys 0.081s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774672,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1137,"lbm_read_time_us":15224,"lbm_reads_lt_1ms":568,"lbm_write_time_us":34024,"lbm_writes_lt_1ms":543,"mutex_wait_us":394,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":2500}
I20260812 06:19:01.720783 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:01.787349 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.066s	user 0.042s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24257,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.787887 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:01.800168 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4772,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.800661 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:02.012383 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.212s	user 0.164s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":14051,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37634,"lbm_writes_lt_1ms":543,"mutex_wait_us":27,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5888,"update_count":2500}
I20260812 06:19:02.012971 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:02.083840 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.071s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19283,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.084507 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:02.099169 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5292,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.100325 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:02.300128 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.200s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":248,"lbm_read_time_us":15589,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29878,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2500}
I20260812 06:19:02.300838 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:02.360111 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.059s	user 0.023s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21336,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.360620 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:02.383428 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3956,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.384052 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:02.567791 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.184s	user 0.126s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":340,"lbm_read_time_us":13737,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29720,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5632,"update_count":2500}
I20260812 06:19:02.568452 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=11.118625
I20260812 06:19:02.607534 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.038s	user 0.027s	sys 0.008s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16239,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:02.608387 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:02.623425 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5409,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.624012 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:02.653107 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":319,"dirs.run_wall_time_us":1467,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1841,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:02.654131 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling LogGCOp(0356a142f93347ea9a83bcb6f1787d85): free 129320502 bytes of WAL
I20260812 06:19:02.654469 28664 log_reader.cc:385] T 0356a142f93347ea9a83bcb6f1787d85: removed 13 log segments from log reader
I20260812 06:19:02.654587 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000014 (ops 67-71)
I20260812 06:19:02.654685 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000015 (ops 72-76)
I20260812 06:19:02.654765 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000016 (ops 77-80)
I20260812 06:19:02.654873 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000017 (ops 81-85)
I20260812 06:19:02.654958 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000018 (ops 86-90)
I20260812 06:19:02.655047 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000019 (ops 91-94)
I20260812 06:19:02.655130 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000020 (ops 95-99)
I20260812 06:19:02.655210 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000021 (ops 100-104)
I20260812 06:19:02.655287 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000022 (ops 105-109)
I20260812 06:19:02.655368 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000023 (ops 110-114)
I20260812 06:19:02.655442 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000024 (ops 115-119)
I20260812 06:19:02.655524 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000025 (ops 120-124)
I20260812 06:19:02.655572 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000026 (ops 125-129)
I20260812 06:19:02.689571 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: LogGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.035s	user 0.000s	sys 0.034s Metrics: {}
I20260812 06:19:02.690008 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=6.157687
I20260812 06:19:02.720885 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13077,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:02.721387 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:02.936342 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.215s	user 0.145s	sys 0.069s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1356,"lbm_read_time_us":13844,"lbm_reads_lt_1ms":669,"lbm_write_time_us":37145,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7680,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:02.937716 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:02.997542 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.060s	user 0.037s	sys 0.022s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":20367,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.998029 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=3.181125
I20260812 06:19:03.023630 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.025s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4919,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:03.024094 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:03.034409 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.034929 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:03.240182 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.205s	user 0.161s	sys 0.044s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877208,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":191,"lbm_read_time_us":15326,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34086,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":3000}
I20260812 06:19:03.240886 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85): 492 bytes on disk
I20260812 06:19:03.241393 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.242175 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:03.292487 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.050s	user 0.035s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21624,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.293181 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:03.310359 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6641,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.311044 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:03.500586 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.189s	user 0.132s	sys 0.057s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":146,"lbm_read_time_us":13954,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31626,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:03.501365 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:03.562688 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.061s	user 0.040s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22107,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.563187 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:03.573975 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.574430 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:03.766325 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.192s	user 0.151s	sys 0.039s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":517,"lbm_read_time_us":13430,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32420,"lbm_writes_lt_1ms":543,"mutex_wait_us":66,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:19:03.769485 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:03.838384 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.068s	user 0.032s	sys 0.035s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23246,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.839115 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:03.859010 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.020s	user 0.018s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7814,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.859668 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:04.045746 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.186s	user 0.145s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1039,"lbm_read_time_us":13544,"lbm_reads_lt_1ms":568,"lbm_write_time_us":30010,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:04.046312 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:04.097738 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.051s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21791,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.098220 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:04.119180 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.021s	user 0.007s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4315,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.119769 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:04.315857 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.196s	user 0.129s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":12726,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31232,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:19:04.316529 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=14.095187
I20260812 06:19:04.364192 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.047s	user 0.024s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20480,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.364784 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:04.376997 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4484,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.377506 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:04.419669 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushMRSOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.042s	user 0.032s	sys 0.007s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":218,"dirs.run_wall_time_us":1371,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1609,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:04.420539 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling LogGCOp(0356a142f93347ea9a83bcb6f1787d85): free 133024646 bytes of WAL
I20260812 06:19:04.420796 28664 log_reader.cc:385] T 0356a142f93347ea9a83bcb6f1787d85: removed 13 log segments from log reader
I20260812 06:19:04.420845 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000027 (ops 130-134)
I20260812 06:19:04.420874 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000028 (ops 135-139)
I20260812 06:19:04.420931 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000029 (ops 140-144)
I20260812 06:19:04.420982 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000030 (ops 145-149)
I20260812 06:19:04.421001 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000031 (ops 150-154)
I20260812 06:19:04.421056 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000032 (ops 155-158)
I20260812 06:19:04.421100 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000033 (ops 159-163)
I20260812 06:19:04.421144 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000034 (ops 164-168)
I20260812 06:19:04.421183 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000035 (ops 169-173)
I20260812 06:19:04.421299 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000036 (ops 174-178)
I20260812 06:19:04.421348 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000037 (ops 179-183)
I20260812 06:19:04.421368 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000038 (ops 184-188)
I20260812 06:19:04.421386 28664 log.cc:1079] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: Deleting log segment in path: /tmp/dist-test-taskfClRFT/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533155601-28075-0/minicluster-data/ts-0-root/wals/0356a142f93347ea9a83bcb6f1787d85/wal-000000039 (ops 189-193)
I20260812 06:19:04.450737 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: LogGCOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.030s	user 0.000s	sys 0.028s Metrics: {}
I20260812 06:19:04.451154 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85): 493 bytes on disk
I20260812 06:19:04.451606 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: UndoDeltaBlockGCOp(0356a142f93347ea9a83bcb6f1787d85) 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:19:04.452181 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=3.181125
I20260812 06:19:04.476138 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.024s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4955,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.476730 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85): perf score=2.188937
I20260812 06:19:04.486907 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: FlushDeltaMemStoresOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3918,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.487449 28776 maintenance_manager.cc:419] P cb0faf7f913c4137b16022e7e510ae61: Scheduling MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85): perf score=1.000000
I20260812 06:19:04.572346 28075 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.350s	user 1.876s	sys 0.233s
I20260812 06:19:04.667652 28075 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.095s	user 0.000s	sys 0.002s
I20260812 06:19:04.668218 28075 tablet_server.cc:179] TabletServer@127.27.106.193:0 shutting down...
I20260812 06:19:04.696043 28664 maintenance_manager.cc:643] P cb0faf7f913c4137b16022e7e510ae61: MajorDeltaCompactionOp(0356a142f93347ea9a83bcb6f1787d85) complete. Timing: real 0.208s	user 0.134s	sys 0.073s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":2272,"lbm_read_time_us":15478,"lbm_reads_lt_1ms":770,"lbm_write_time_us":32855,"lbm_writes_lt_1ms":743,"mutex_wait_us":410,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":22400,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:19:04.696708 28075 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:04.697089 28075 tablet_replica.cc:333] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61: stopping tablet replica
I20260812 06:19:04.697273 28075 raft_consensus.cc:2243] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.697463 28075 raft_consensus.cc:2272] T 0356a142f93347ea9a83bcb6f1787d85 P cb0faf7f913c4137b16022e7e510ae61 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.717291 28075 tablet_server.cc:196] TabletServer@127.27.106.193:0 shutdown complete.
I20260812 06:19:04.753847 28075 master.cc:562] Master@127.27.106.254:45893 shutting down...
I20260812 06:19:04.757606 28075 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.757787 28075 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:04.757839 28075 tablet_replica.cc:333] T 00000000000000000000000000000000 P 79b9f4a4363141aa91dec4a97ae14880: stopping tablet replica
I20260812 06:19:04.770190 28075 master.cc:584] Master@127.27.106.254:45893 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5885 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11696 ms total)

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