[==========] 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:30.139307  7398 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.57.190:45833
I20260812 06:18:30.140360  7398 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:30.140946  7398 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:30.147186  7416 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:30.147217  7398 server_base.cc:1061] running on GCE node
W20260812 06:18:30.147511  7414 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:30.147562  7412 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:30.148046  7398 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:30.148135  7398 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:30.148165  7398 hybrid_clock.cc:648] HybridClock initialized: now 1786515510148164 us; error 0 us; skew 500 ppm
I20260812 06:18:30.149852  7398 webserver.cc:533] Webserver started at http://127.7.57.190:40935/ using document root <none> and password file <none>
I20260812 06:18:30.150343  7398 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:30.150399  7398 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:30.150605  7398 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:30.152246  7398 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/master-0-root/instance:
uuid: "72ef3993941a427b9c598b7a9e31a3df"
format_stamp: "Formatted at 2026-08-12 06:18:30 on dist-test-slave-21b9"
I20260812 06:18:30.155606  7398 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.002s	sys 0.002s
I20260812 06:18:30.157554  7428 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:30.158562  7398 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:30.158663  7398 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/master-0-root
uuid: "72ef3993941a427b9c598b7a9e31a3df"
format_stamp: "Formatted at 2026-08-12 06:18:30 on dist-test-slave-21b9"
I20260812 06:18:30.158741  7398 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-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:30.211654  7398 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:30.212296  7398 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:30.212442  7398 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:30.220288  7398 rpc_server.cc:307] RPC server started. Bound to: 127.7.57.190:45833
I20260812 06:18:30.220337  7515 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.57.190:45833 every 8 connection(s)
I20260812 06:18:30.222573  7516 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:30.228139  7516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: Bootstrap starting.
I20260812 06:18:30.230501  7516 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:30.231443  7516 log.cc:826] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:30.233155  7516 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: No bootstrap required, opened a new log
I20260812 06:18:30.235941  7516 raft_consensus.cc:359] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER }
I20260812 06:18:30.236114  7516 raft_consensus.cc:385] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:30.236192  7516 raft_consensus.cc:740] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 72ef3993941a427b9c598b7a9e31a3df, State: Initialized, Role: FOLLOWER
I20260812 06:18:30.236763  7516 consensus_queue.cc:260] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [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: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER }
I20260812 06:18:30.236913  7516 raft_consensus.cc:399] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:30.236979  7516 raft_consensus.cc:493] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:30.237095  7516 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:30.237870  7516 raft_consensus.cc:515] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER }
I20260812 06:18:30.238296  7516 leader_election.cc:304] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [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: 72ef3993941a427b9c598b7a9e31a3df; no voters: 
I20260812 06:18:30.238595  7516 leader_election.cc:290] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:30.238729  7525 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:30.238962  7525 raft_consensus.cc:697] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 1 LEADER]: Becoming Leader. State: Replica: 72ef3993941a427b9c598b7a9e31a3df, State: Running, Role: LEADER
I20260812 06:18:30.239409  7525 consensus_queue.cc:237] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [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: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER }
I20260812 06:18:30.239552  7516 sys_catalog.cc:565] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:30.241312  7526 sys_catalog.cc:455] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "72ef3993941a427b9c598b7a9e31a3df" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER } }
I20260812 06:18:30.241431  7526 sys_catalog.cc:458] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:30.241693  7528 sys_catalog.cc:455] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [sys.catalog]: SysCatalogTable state changed. Reason: New leader 72ef3993941a427b9c598b7a9e31a3df. Latest consensus state: current_term: 1 leader_uuid: "72ef3993941a427b9c598b7a9e31a3df" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "72ef3993941a427b9c598b7a9e31a3df" member_type: VOTER } }
I20260812 06:18:30.241732  7398 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:30.241783  7528 sys_catalog.cc:458] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:30.241793  7546 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:30.243889  7546 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:30.248436  7546 catalog_manager.cc:1383] Generated new cluster ID: c986803089664179b953d1e0b5c5a7a3
I20260812 06:18:30.248510  7546 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:30.259114  7546 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:30.259958  7546 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:30.265460  7546 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: Generated new TSK 0
I20260812 06:18:30.266038  7546 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:30.274183  7398 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:30.276703  7556 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:30.276844  7557 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:30.276850  7398 server_base.cc:1061] running on GCE node
W20260812 06:18:30.276995  7559 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:30.277184  7398 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:30.277238  7398 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:30.277259  7398 hybrid_clock.cc:648] HybridClock initialized: now 1786515510277259 us; error 0 us; skew 500 ppm
I20260812 06:18:30.278163  7398 webserver.cc:533] Webserver started at http://127.7.57.129:45447/ using document root <none> and password file <none>
I20260812 06:18:30.278334  7398 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:30.278393  7398 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:30.278465  7398 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:30.278896  7398 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/instance:
uuid: "f5914faee9e447d2a02f95f6ea2dd872"
format_stamp: "Formatted at 2026-08-12 06:18:30 on dist-test-slave-21b9"
I20260812 06:18:30.280694  7398 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:30.281788  7568 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:30.282033  7398 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:30.282095  7398 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root
uuid: "f5914faee9e447d2a02f95f6ea2dd872"
format_stamp: "Formatted at 2026-08-12 06:18:30 on dist-test-slave-21b9"
I20260812 06:18:30.282162  7398 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-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:30.295470  7398 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:30.296154  7398 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:30.296623  7398 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:30.297468  7398 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:30.297521  7398 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:30.297578  7398 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:30.297612  7398 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:30.303351  7398 rpc_server.cc:307] RPC server started. Bound to: 127.7.57.129:41695
I20260812 06:18:30.303400  7669 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.57.129:41695 every 8 connection(s)
I20260812 06:18:30.312901  7670 heartbeater.cc:344] Connected to a master server at 127.7.57.190:45833
I20260812 06:18:30.313143  7670 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:30.313539  7670 heartbeater.cc:507] Master 127.7.57.190:45833 requested a full tablet report, sending...
I20260812 06:18:30.314960  7456 ts_manager.cc:194] Registered new tserver with Master: f5914faee9e447d2a02f95f6ea2dd872 (127.7.57.129:41695)
I20260812 06:18:30.315086  7398 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.011139582s
I20260812 06:18:30.316511  7456 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44304
I20260812 06:18:30.324728  7456 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44320:
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:30.339123  7614 tablet_service.cc:1511] Processing CreateTablet for tablet 4fb929d2b9614cb1b5c2cc49677bd267 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4a7724ad5e464caf8b38d6f731a83118]), partition=
I20260812 06:18:30.339609  7614 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 4fb929d2b9614cb1b5c2cc49677bd267. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:30.341807  7689 tablet_bootstrap.cc:492] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Bootstrap starting.
I20260812 06:18:30.342859  7689 tablet_bootstrap.cc:654] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:30.343885  7689 tablet_bootstrap.cc:492] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: No bootstrap required, opened a new log
I20260812 06:18:30.343969  7689 ts_tablet_manager.cc:1403] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:30.344461  7689 raft_consensus.cc:359] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5914faee9e447d2a02f95f6ea2dd872" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 41695 } }
I20260812 06:18:30.344604  7689 raft_consensus.cc:385] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:30.344632  7689 raft_consensus.cc:740] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f5914faee9e447d2a02f95f6ea2dd872, State: Initialized, Role: FOLLOWER
I20260812 06:18:30.344759  7689 consensus_queue.cc:260] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [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: "f5914faee9e447d2a02f95f6ea2dd872" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 41695 } }
I20260812 06:18:30.344839  7689 raft_consensus.cc:399] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:30.344877  7689 raft_consensus.cc:493] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:30.344928  7689 raft_consensus.cc:3060] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:30.345667  7689 raft_consensus.cc:515] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5914faee9e447d2a02f95f6ea2dd872" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 41695 } }
I20260812 06:18:30.345834  7689 leader_election.cc:304] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [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: f5914faee9e447d2a02f95f6ea2dd872; no voters: 
I20260812 06:18:30.346050  7689 leader_election.cc:290] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:30.346170  7693 raft_consensus.cc:2804] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:30.346444  7689 ts_tablet_manager.cc:1434] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:30.346414  7693 raft_consensus.cc:697] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 1 LEADER]: Becoming Leader. State: Replica: f5914faee9e447d2a02f95f6ea2dd872, State: Running, Role: LEADER
I20260812 06:18:30.346839  7670 heartbeater.cc:499] Master 127.7.57.190:45833 was elected leader, sending a full tablet report...
I20260812 06:18:30.346949  7693 consensus_queue.cc:237] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [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: "f5914faee9e447d2a02f95f6ea2dd872" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 41695 } }
I20260812 06:18:30.349373  7456 catalog_manager.cc:5719] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 reported cstate change: term changed from 0 to 1, leader changed from <none> to f5914faee9e447d2a02f95f6ea2dd872 (127.7.57.129). New cstate: current_term: 1 leader_uuid: "f5914faee9e447d2a02f95f6ea2dd872" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f5914faee9e447d2a02f95f6ea2dd872" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 41695 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:30.422771  7398 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.021s	sys 0.011s
I20260812 06:18:30.554389  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=19.054940
I20260812 06:18:30.728483  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.174s	user 0.122s	sys 0.041s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":904,"drs_written":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":756,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":107,"threads_started":1,"update_count":1500}
I20260812 06:18:30.729626  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267): free 20743880 bytes of WAL
I20260812 06:18:30.729952  7577 log_reader.cc:385] T 4fb929d2b9614cb1b5c2cc49677bd267: removed 2 log segments from log reader
I20260812 06:18:30.730031  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000001 (ops 1-6)
I20260812 06:18:30.730093  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000002 (ops 7-11)
I20260812 06:18:30.733928  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:18:30.734308  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:30.752966  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.018s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5982,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.753655  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267): 16411392 bytes on disk
I20260812 06:18:30.754190  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267) 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:30.754622  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:30.885598  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.131s	user 0.079s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":638,"lbm_read_time_us":7040,"lbm_reads_lt_1ms":460,"lbm_write_time_us":22640,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":284,"threads_started":5,"update_count":2000}
I20260812 06:18:30.886158  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:30.917325  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13201,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:30.917804  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:30.929816  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4188,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:30.930286  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.047999  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.118s	user 0.102s	sys 0.016s 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":806,"lbm_read_time_us":7553,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23362,"lbm_writes_lt_1ms":443,"mutex_wait_us":317,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":2000}
I20260812 06:18:31.048467  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:31.086234  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.038s	user 0.013s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13622,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.086717  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.096756  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3741,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.097195  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.219564  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.122s	user 0.116s	sys 0.006s 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":1211,"lbm_read_time_us":8627,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21562,"lbm_writes_lt_1ms":443,"mutex_wait_us":347,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21120,"update_count":2000}
I20260812 06:18:31.220065  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:31.272130  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.052s	user 0.033s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16872,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.272677  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.283090  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3860,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.283655  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.430521  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.147s	user 0.099s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":221,"lbm_read_time_us":10818,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24216,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:31.431193  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:31.475071  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.044s	user 0.010s	sys 0.017s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.475600  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.486186  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3849,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.486714  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.597843  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.111s	user 0.083s	sys 0.028s 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":237,"lbm_read_time_us":7941,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20546,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:18:31.598313  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:31.631969  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.033s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13085,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.632436  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.642622  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3753,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.643222  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.761152  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.118s	user 0.101s	sys 0.017s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":610,"lbm_read_time_us":8136,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22799,"lbm_writes_lt_1ms":443,"mutex_wait_us":4,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":567040,"update_count":2000}
I20260812 06:18:31.761690  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:31.808962  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.047s	user 0.029s	sys 0.010s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":14044,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:31.809621  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.825093  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5914,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.825623  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:31.865197  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.039s	user 0.025s	sys 0.004s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":233,"dirs.run_wall_time_us":1365,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1496,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:31.866091  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267): free 112239310 bytes of WAL
I20260812 06:18:31.866323  7577 log_reader.cc:385] T 4fb929d2b9614cb1b5c2cc49677bd267: removed 11 log segments from log reader
I20260812 06:18:31.866387  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000003 (ops 12-16)
I20260812 06:18:31.866427  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000004 (ops 17-21)
I20260812 06:18:31.866451  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000005 (ops 22-26)
I20260812 06:18:31.866472  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000006 (ops 27-31)
I20260812 06:18:31.866493  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000007 (ops 32-36)
I20260812 06:18:31.866514  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000008 (ops 37-41)
I20260812 06:18:31.866541  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000009 (ops 42-46)
I20260812 06:18:31.866575  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000010 (ops 47-51)
I20260812 06:18:31.866606  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000011 (ops 52-56)
I20260812 06:18:31.866627  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000012 (ops 57-60)
I20260812 06:18:31.866654  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000013 (ops 61-65)
I20260812 06:18:31.891530  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:31.891908  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.912413  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.020s	user 0.008s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.912892  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:31.922811  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3627,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:31.923411  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267): 447 bytes on disk
I20260812 06:18:31.923966  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:18:31.924471  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:32.123034  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.198s	user 0.127s	sys 0.065s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877338,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":688,"lbm_read_time_us":12473,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32735,"lbm_writes_lt_1ms":643,"mutex_wait_us":83,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:32.123715  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:32.166726  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.043s	user 0.019s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18612,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.167308  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:32.317866  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.150s	user 0.091s	sys 0.048s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":563,"lbm_read_time_us":8270,"lbm_reads_lt_1ms":463,"lbm_write_time_us":23234,"lbm_writes_lt_1ms":443,"mutex_wait_us":268,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:32.318393  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:32.371616  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.053s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23849,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.372138  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:32.383790  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.011s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.384357  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:32.563630  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.179s	user 0.123s	sys 0.039s 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":313,"lbm_read_time_us":11111,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26888,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:18:32.564109  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:32.612872  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.049s	user 0.028s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20408,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:32.613370  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:32.624179  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3933,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.624758  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:32.769335  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.144s	user 0.100s	sys 0.044s 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":244,"lbm_read_time_us":9461,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28181,"lbm_writes_lt_1ms":543,"mutex_wait_us":83,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:18:32.769942  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:32.798800  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.029s	user 0.018s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11997,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.799348  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:32.811625  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.012s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4624,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.812039  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:32.932380  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.120s	user 0.084s	sys 0.036s 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":899,"lbm_read_time_us":7794,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23916,"lbm_writes_lt_1ms":443,"mutex_wait_us":233,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:18:32.932963  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:32.974546  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.041s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":14142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:32.975016  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:32.990015  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5389,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:32.990831  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:33.112661  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.122s	user 0.100s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672279,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":187,"lbm_read_time_us":8177,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23736,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.113214  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=10.126437
I20260812 06:18:33.161494  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.048s	user 0.029s	sys 0.006s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12569,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:33.162003  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:33.172259  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3802,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.172691  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:33.204638  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.032s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":231,"dirs.run_wall_time_us":1366,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1811,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:33.205610  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:33.350878  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.145s	user 0.074s	sys 0.065s 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":149,"lbm_read_time_us":8057,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22606,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.351573  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267): free 120100330 bytes of WAL
I20260812 06:18:33.351886  7577 log_reader.cc:385] T 4fb929d2b9614cb1b5c2cc49677bd267: removed 12 log segments from log reader
I20260812 06:18:33.351975  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000014 (ops 66-70)
I20260812 06:18:33.352035  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000015 (ops 71-75)
I20260812 06:18:33.352080  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000016 (ops 76-80)
I20260812 06:18:33.352120  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000017 (ops 81-84)
I20260812 06:18:33.352157  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000018 (ops 85-89)
I20260812 06:18:33.352192  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000019 (ops 90-94)
I20260812 06:18:33.352231  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000020 (ops 95-98)
I20260812 06:18:33.352303  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000021 (ops 99-103)
I20260812 06:18:33.352340  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000022 (ops 104-108)
I20260812 06:18:33.352365  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000023 (ops 109-113)
I20260812 06:18:33.352419  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000024 (ops 114-118)
I20260812 06:18:33.352481  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000025 (ops 119-122)
I20260812 06:18:33.371479  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.020s	user 0.004s	sys 0.016s Metrics: {}
I20260812 06:18:33.371889  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:33.427326  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.055s	user 0.026s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24626,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.428121  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:33.454784  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.026s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6538,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.455386  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:33.473519  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.018s	user 0.005s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4225,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.474067  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:33.672062  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.198s	user 0.142s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":167,"lbm_read_time_us":14459,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33266,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":3000}
I20260812 06:18:33.672698  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267): 447 bytes on disk
I20260812 06:18:33.673074  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:33.673604  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:33.729480  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.056s	user 0.015s	sys 0.039s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":19653,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.730080  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:33.741154  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3827,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.741704  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:33.928772  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.187s	user 0.128s	sys 0.048s 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":551,"lbm_read_time_us":11921,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29437,"lbm_writes_lt_1ms":543,"mutex_wait_us":41,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":2500}
I20260812 06:18:33.929281  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=14.095187
I20260812 06:18:33.974061  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.045s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17314,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:33.974586  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:33.989972  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5762,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:33.990538  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:34.157649  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.167s	user 0.116s	sys 0.044s 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":192,"lbm_read_time_us":13620,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":571,"lbm_write_time_us":26605,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:18:34.158339  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=11.118625
I20260812 06:18:34.192924  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.034s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14526,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:34.193486  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.217270  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.024s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4359,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.217728  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.228335  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3908,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.228765  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:34.395673  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.167s	user 0.121s	sys 0.036s 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":207,"lbm_read_time_us":8764,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31014,"lbm_writes_lt_1ms":543,"mutex_wait_us":31,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":35456,"update_count":2500}
I20260812 06:18:34.396277  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=11.118625
I20260812 06:18:34.426455  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":11798,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:34.427001  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.449164  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.022s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4659,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.449697  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.459653  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3654,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:34.460254  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:34.607409  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.147s	user 0.104s	sys 0.041s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774798,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":542,"lbm_read_time_us":11056,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28941,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:18:34.608031  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=11.118625
I20260812 06:18:34.637431  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.029s	user 0.018s	sys 0.009s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12320,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:34.638010  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.653976  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5869,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.654464  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:34.704213  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushMRSOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.050s	user 0.022s	sys 0.006s Metrics: {"bytes_written":1275445,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1436,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1751,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:34.704988  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267): free 121459726 bytes of WAL
I20260812 06:18:34.705228  7577 log_reader.cc:385] T 4fb929d2b9614cb1b5c2cc49677bd267: removed 12 log segments from log reader
I20260812 06:18:34.705289  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000026 (ops 123-127)
I20260812 06:18:34.705331  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000027 (ops 128-132)
I20260812 06:18:34.705366  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000028 (ops 133-137)
I20260812 06:18:34.705389  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000029 (ops 138-142)
I20260812 06:18:34.705410  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000030 (ops 143-147)
I20260812 06:18:34.705430  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000031 (ops 148-152)
I20260812 06:18:34.705458  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000032 (ops 153-157)
I20260812 06:18:34.705487  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000033 (ops 158-162)
I20260812 06:18:34.705518  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000034 (ops 163-167)
I20260812 06:18:34.705547  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000035 (ops 168-172)
I20260812 06:18:34.705571  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000036 (ops 173-177)
I20260812 06:18:34.705596  7577 log.cc:1079] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/4fb929d2b9614cb1b5c2cc49677bd267/wal-000000037 (ops 178-182)
I20260812 06:18:34.730692  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: LogGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.026s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:34.731137  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=7.149875
I20260812 06:18:34.754591  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.023s	user 0.016s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":9474,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:34.755138  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=2.188937
I20260812 06:18:34.774698  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.019s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5338,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:34.775154  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267): 482 bytes on disk
I20260812 06:18:34.775681  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: UndoDeltaBlockGCOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:34.776326  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:34.982157  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.206s	user 0.131s	sys 0.071s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979734,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":439,"lbm_read_time_us":15062,"lbm_reads_lt_1ms":766,"lbm_write_time_us":36005,"lbm_writes_lt_1ms":743,"mutex_wait_us":34,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":12288,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:18:34.982769  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=15.087375
I20260812 06:18:35.046866  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.064s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":20360,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:18:35.047478  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=6.157687
I20260812 06:18:35.066068  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: FlushDeltaMemStoresOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.018s	user 0.011s	sys 0.005s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":7105,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:35.066671  7671 maintenance_manager.cc:419] P f5914faee9e447d2a02f95f6ea2dd872: Scheduling MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267): perf score=1.000000
I20260812 06:18:35.093040  7398 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.670s	user 1.643s	sys 0.154s
I20260812 06:18:35.177314  7398 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.084s	user 0.001s	sys 0.000s
I20260812 06:18:35.177935  7398 tablet_server.cc:179] TabletServer@127.7.57.129:0 shutting down...
I20260812 06:18:35.233678  7577 maintenance_manager.cc:643] P f5914faee9e447d2a02f95f6ea2dd872: MajorDeltaCompactionOp(4fb929d2b9614cb1b5c2cc49677bd267) complete. Timing: real 0.167s	user 0.110s	sys 0.057s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":623,"lbm_read_time_us":13963,"lbm_reads_lt_1ms":668,"lbm_write_time_us":27056,"lbm_writes_lt_1ms":643,"mutex_wait_us":278,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":3000}
I20260812 06:18:35.234290  7398 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:35.234724  7398 tablet_replica.cc:333] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872: stopping tablet replica
I20260812 06:18:35.234946  7398 raft_consensus.cc:2243] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:35.235178  7398 raft_consensus.cc:2272] T 4fb929d2b9614cb1b5c2cc49677bd267 P f5914faee9e447d2a02f95f6ea2dd872 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:35.250739  7398 tablet_server.cc:196] TabletServer@127.7.57.129:0 shutdown complete.
I20260812 06:18:35.285456  7398 master.cc:562] Master@127.7.57.190:45833 shutting down...
I20260812 06:18:35.288815  7398 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:35.288992  7398 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:35.289068  7398 tablet_replica.cc:333] T 00000000000000000000000000000000 P 72ef3993941a427b9c598b7a9e31a3df: stopping tablet replica
I20260812 06:18:35.301213  7398 master.cc:584] Master@127.7.57.190:45833 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5235 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:35.383705  7398 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.57.190:36481
I20260812 06:18:35.384114  7398 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:35.386041  7718 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:35.386155  7724 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:35.386161  7719 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:35.386233  7398 server_base.cc:1061] running on GCE node
I20260812 06:18:35.386452  7398 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:35.386494  7398 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:35.386509  7398 hybrid_clock.cc:648] HybridClock initialized: now 1786515515386509 us; error 0 us; skew 500 ppm
I20260812 06:18:35.387301  7398 webserver.cc:533] Webserver started at http://127.7.57.190:33239/ using document root <none> and password file <none>
I20260812 06:18:35.387444  7398 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:35.387483  7398 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:35.387542  7398 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:35.387866  7398 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/master-0-root/instance:
uuid: "bff5a2b096da4c0da6091ec708e0e8f9"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-21b9"
I20260812 06:18:35.389253  7398 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:35.390089  7731 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:35.390291  7398 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:35.390360  7398 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/master-0-root
uuid: "bff5a2b096da4c0da6091ec708e0e8f9"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-21b9"
I20260812 06:18:35.390430  7398 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-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:35.400290  7398 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:35.400643  7398 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:35.405206  7398 rpc_server.cc:307] RPC server started. Bound to: 127.7.57.190:36481
I20260812 06:18:35.411741  7822 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.57.190:36481 every 8 connection(s)
I20260812 06:18:35.412192  7823 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:35.413949  7823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9: Bootstrap starting.
I20260812 06:18:35.414729  7823 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:35.416317  7823 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9: No bootstrap required, opened a new log
I20260812 06:18:35.416678  7823 raft_consensus.cc:359] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER }
I20260812 06:18:35.416764  7823 raft_consensus.cc:385] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:35.416790  7823 raft_consensus.cc:740] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: bff5a2b096da4c0da6091ec708e0e8f9, State: Initialized, Role: FOLLOWER
I20260812 06:18:35.416901  7823 consensus_queue.cc:260] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [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: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER }
I20260812 06:18:35.416980  7823 raft_consensus.cc:399] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:35.417017  7823 raft_consensus.cc:493] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:35.417052  7823 raft_consensus.cc:3060] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:35.417682  7823 raft_consensus.cc:515] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER }
I20260812 06:18:35.417793  7823 leader_election.cc:304] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [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: bff5a2b096da4c0da6091ec708e0e8f9; no voters: 
I20260812 06:18:35.417937  7823 leader_election.cc:290] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:35.418051  7827 raft_consensus.cc:2804] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:35.418242  7827 raft_consensus.cc:697] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 1 LEADER]: Becoming Leader. State: Replica: bff5a2b096da4c0da6091ec708e0e8f9, State: Running, Role: LEADER
I20260812 06:18:35.418354  7823 sys_catalog.cc:565] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:35.418368  7827 consensus_queue.cc:237] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [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: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER }
I20260812 06:18:35.418826  7828 sys_catalog.cc:455] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER } }
I20260812 06:18:35.418848  7829 sys_catalog.cc:455] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [sys.catalog]: SysCatalogTable state changed. Reason: New leader bff5a2b096da4c0da6091ec708e0e8f9. Latest consensus state: current_term: 1 leader_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "bff5a2b096da4c0da6091ec708e0e8f9" member_type: VOTER } }
I20260812 06:18:35.418928  7828 sys_catalog.cc:458] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:35.418932  7829 sys_catalog.cc:458] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:35.419489  7835 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:35.420285  7835 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:35.421346  7398 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:35.422137  7835 catalog_manager.cc:1383] Generated new cluster ID: 9d4523e93b6e45bcaba477b161820845
I20260812 06:18:35.422183  7835 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:35.432964  7835 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:35.433465  7835 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:35.446322  7835 catalog_manager.cc:6092] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9: Generated new TSK 0
I20260812 06:18:35.446542  7835 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:35.453555  7398 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:35.455474  7855 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:35.455708  7398 server_base.cc:1061] running on GCE node
W20260812 06:18:35.455714  7859 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:35.455801  7857 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:35.456040  7398 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:35.456094  7398 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:35.456108  7398 hybrid_clock.cc:648] HybridClock initialized: now 1786515515456109 us; error 0 us; skew 500 ppm
I20260812 06:18:35.456938  7398 webserver.cc:533] Webserver started at http://127.7.57.129:33017/ using document root <none> and password file <none>
I20260812 06:18:35.457075  7398 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:35.457119  7398 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:35.457172  7398 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:35.457500  7398 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/instance:
uuid: "e56e9f437c724dfe9d996866da2e1218"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-21b9"
I20260812 06:18:35.458875  7398 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:35.459765  7867 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:35.460000  7398 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:18:35.460079  7398 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root
uuid: "e56e9f437c724dfe9d996866da2e1218"
format_stamp: "Formatted at 2026-08-12 06:18:35 on dist-test-slave-21b9"
I20260812 06:18:35.460144  7398 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-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:35.474272  7398 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:35.474642  7398 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:35.474913  7398 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:35.475427  7398 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:35.475469  7398 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:35.475515  7398 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:35.475545  7398 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:35.479745  7398 rpc_server.cc:307] RPC server started. Bound to: 127.7.57.129:34307
I20260812 06:18:35.479799  7981 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.57.129:34307 every 8 connection(s)
I20260812 06:18:35.488778  7982 heartbeater.cc:344] Connected to a master server at 127.7.57.190:36481
I20260812 06:18:35.488889  7982 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:35.489138  7982 heartbeater.cc:507] Master 127.7.57.190:36481 requested a full tablet report, sending...
I20260812 06:18:35.489738  7764 ts_manager.cc:194] Registered new tserver with Master: e56e9f437c724dfe9d996866da2e1218 (127.7.57.129:34307)
I20260812 06:18:35.490108  7398 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009967628s
I20260812 06:18:35.490694  7764 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:35914
I20260812 06:18:35.497150  7764 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:35922:
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:35.505705  7919 tablet_service.cc:1511] Processing CreateTablet for tablet 88570c24cf0542bd9870d9052af98f82 (DEFAULT_TABLE table=heavy-update-compaction-test [id=205e144428984d59b003eb64e9435a24]), partition=
I20260812 06:18:35.505985  7919 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 88570c24cf0542bd9870d9052af98f82. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:35.507973  8008 tablet_bootstrap.cc:492] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Bootstrap starting.
I20260812 06:18:35.508806  8008 tablet_bootstrap.cc:654] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:35.509802  8008 tablet_bootstrap.cc:492] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: No bootstrap required, opened a new log
I20260812 06:18:35.509884  8008 ts_tablet_manager.cc:1403] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:35.510262  8008 raft_consensus.cc:359] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e56e9f437c724dfe9d996866da2e1218" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 34307 } }
I20260812 06:18:35.510351  8008 raft_consensus.cc:385] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:35.510383  8008 raft_consensus.cc:740] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e56e9f437c724dfe9d996866da2e1218, State: Initialized, Role: FOLLOWER
I20260812 06:18:35.510502  8008 consensus_queue.cc:260] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [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: "e56e9f437c724dfe9d996866da2e1218" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 34307 } }
I20260812 06:18:35.510581  8008 raft_consensus.cc:399] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:35.510620  8008 raft_consensus.cc:493] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:35.510667  8008 raft_consensus.cc:3060] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:35.511498  8008 raft_consensus.cc:515] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e56e9f437c724dfe9d996866da2e1218" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 34307 } }
I20260812 06:18:35.511629  8008 leader_election.cc:304] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [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: e56e9f437c724dfe9d996866da2e1218; no voters: 
I20260812 06:18:35.511814  8008 leader_election.cc:290] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:35.511925  8011 raft_consensus.cc:2804] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:35.512099  8008 ts_tablet_manager.cc:1434] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:35.512123  8011 raft_consensus.cc:697] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 1 LEADER]: Becoming Leader. State: Replica: e56e9f437c724dfe9d996866da2e1218, State: Running, Role: LEADER
I20260812 06:18:35.512140  7982 heartbeater.cc:499] Master 127.7.57.190:36481 was elected leader, sending a full tablet report...
I20260812 06:18:35.512336  8011 consensus_queue.cc:237] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [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: "e56e9f437c724dfe9d996866da2e1218" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 34307 } }
I20260812 06:18:35.513597  7764 catalog_manager.cc:5719] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 reported cstate change: term changed from 0 to 1, leader changed from <none> to e56e9f437c724dfe9d996866da2e1218 (127.7.57.129). New cstate: current_term: 1 leader_uuid: "e56e9f437c724dfe9d996866da2e1218" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e56e9f437c724dfe9d996866da2e1218" member_type: VOTER last_known_addr { host: "127.7.57.129" port: 34307 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:35.573565  7398 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.010s	sys 0.012s
I20260812 06:18:35.730600  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushMRSOp(88570c24cf0542bd9870d9052af98f82): perf score=23.023690
I20260812 06:18:35.886166  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushMRSOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.155s	user 0.121s	sys 0.031s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":714,"drs_written":1,"lbm_read_time_us":35,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41240,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:18:35.886801  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling LogGCOp(88570c24cf0542bd9870d9052af98f82): free 20743880 bytes of WAL
I20260812 06:18:35.887027  7878 log_reader.cc:385] T 88570c24cf0542bd9870d9052af98f82: removed 2 log segments from log reader
I20260812 06:18:35.887077  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000001 (ops 1-6)
I20260812 06:18:35.887107  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000002 (ops 7-11)
I20260812 06:18:35.890969  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: LogGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:35.891474  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:35.905810  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:35.906253  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.052307  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.146s	user 0.110s	sys 0.035s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":9742,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24344,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":292,"threads_started":5,"update_count":2000}
I20260812 06:18:36.052857  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82): 20513813 bytes on disk
I20260812 06:18:36.053293  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:18:36.053766  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=11.118625
I20260812 06:18:36.095418  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.042s	user 0.022s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13422,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:36.096051  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:36.110376  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5431,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:36.110915  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.254981  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.144s	user 0.096s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":613,"lbm_read_time_us":10270,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23855,"lbm_writes_lt_1ms":443,"mutex_wait_us":280,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:18:36.255635  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=10.126437
I20260812 06:18:36.297417  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.042s	user 0.015s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13643,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.297876  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:36.308714  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4008,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.309333  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.423533  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.114s	user 0.102s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":8157,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20451,"lbm_writes_lt_1ms":443,"mutex_wait_us":284,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19456,"update_count":2000}
I20260812 06:18:36.423997  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=10.126437
I20260812 06:18:36.459041  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.035s	user 0.013s	sys 0.014s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12753,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.459663  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:36.475732  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.476315  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.601707  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.125s	user 0.093s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":998,"lbm_read_time_us":10115,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23063,"lbm_writes_lt_1ms":443,"mutex_wait_us":235,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":2000}
I20260812 06:18:36.602222  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=10.126437
I20260812 06:18:36.642922  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.041s	user 0.023s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":14185,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.643558  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:36.654712  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.655326  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.780576  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.125s	user 0.088s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":626,"lbm_read_time_us":10147,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21356,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":34048,"update_count":2000}
I20260812 06:18:36.781046  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=10.126437
I20260812 06:18:36.830449  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.049s	user 0.013s	sys 0.023s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":13635,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:36.831135  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:36.842020  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4070,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:36.842483  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:36.984867  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.142s	user 0.110s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":143,"lbm_read_time_us":10632,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21336,"lbm_writes_lt_1ms":443,"mutex_wait_us":38,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23296,"update_count":2000}
I20260812 06:18:36.985702  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=10.126437
I20260812 06:18:37.020812  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.035s	user 0.026s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13336,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:37.021358  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:37.032402  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3934,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.033185  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushMRSOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:37.058688  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushMRSOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.025s	user 0.023s	sys 0.001s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":191,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1271,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1351,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:37.059368  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling LogGCOp(88570c24cf0542bd9870d9052af98f82): free 112692363 bytes of WAL
I20260812 06:18:37.059569  7878 log_reader.cc:385] T 88570c24cf0542bd9870d9052af98f82: removed 11 log segments from log reader
I20260812 06:18:37.059614  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000003 (ops 12-16)
I20260812 06:18:37.059641  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000004 (ops 17-21)
I20260812 06:18:37.059674  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000005 (ops 22-26)
I20260812 06:18:37.059703  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000006 (ops 27-31)
I20260812 06:18:37.059736  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000007 (ops 32-36)
I20260812 06:18:37.059767  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000008 (ops 37-41)
I20260812 06:18:37.059798  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000009 (ops 42-46)
I20260812 06:18:37.059830  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000010 (ops 47-51)
I20260812 06:18:37.059861  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000011 (ops 52-56)
I20260812 06:18:37.059891  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000012 (ops 57-61)
I20260812 06:18:37.059922  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000013 (ops 62-66)
I20260812 06:18:37.080427  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: LogGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.021s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:18:37.080847  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=3.181125
I20260812 06:18:37.102715  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.022s	user 0.001s	sys 0.014s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":3958,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:37.103296  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:37.112875  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3544,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:37.113438  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82): 447 bytes on disk
I20260812 06:18:37.113938  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:18:37.114476  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:37.305920  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.191s	user 0.123s	sys 0.068s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":610,"lbm_read_time_us":14123,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31038,"lbm_writes_lt_1ms":643,"mutex_wait_us":95,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"thread_start_us":77,"threads_started":1,"update_count":3000}
I20260812 06:18:37.306524  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:37.365293  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.059s	user 0.026s	sys 0.031s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22166,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.365938  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:37.382266  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.016s	user 0.003s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6822,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.382843  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:37.557554  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.175s	user 0.122s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":701,"lbm_read_time_us":13403,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26330,"lbm_writes_lt_1ms":543,"mutex_wait_us":297,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14976,"update_count":2500}
I20260812 06:18:37.558094  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:37.605247  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.047s	user 0.011s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18031,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.605796  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:37.631076  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.025s	user 0.008s	sys 0.013s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7566,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.631726  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:37.818953  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.187s	user 0.142s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":195,"lbm_read_time_us":14240,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29910,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":2500}
I20260812 06:18:37.819548  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:37.872246  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.053s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23934,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:37.872833  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:37.887910  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4931,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:37.888370  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:38.074470  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.186s	user 0.125s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":12037,"lbm_reads_lt_1ms":568,"lbm_write_time_us":28790,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":625920,"update_count":2500}
I20260812 06:18:38.075098  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:38.130892  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.056s	user 0.032s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":24095,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:38.131488  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:38.156317  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.025s	user 0.005s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6150,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.156801  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:38.167990  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4100,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.168678  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:38.378847  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.210s	user 0.133s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918211,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":115,"lbm_read_time_us":13515,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33574,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":46976,"update_count":3000}
I20260812 06:18:38.379601  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=15.087375
I20260812 06:18:38.446377  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.067s	user 0.021s	sys 0.033s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":19436,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:18:38.447116  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=6.157687
I20260812 06:18:38.471226  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.024s	user 0.017s	sys 0.004s Metrics: {"bytes_written":7794837,"delete_count":0,"lbm_write_time_us":10050,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:18:38.471778  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushMRSOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:38.504714  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushMRSOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.033s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":240,"dirs.run_wall_time_us":1550,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1323,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:18:38.505512  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling LogGCOp(88570c24cf0542bd9870d9052af98f82): free 123804191 bytes of WAL
I20260812 06:18:38.505743  7878 log_reader.cc:385] T 88570c24cf0542bd9870d9052af98f82: removed 12 log segments from log reader
I20260812 06:18:38.505792  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000014 (ops 67-71)
I20260812 06:18:38.505831  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000015 (ops 72-76)
I20260812 06:18:38.505862  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000016 (ops 77-81)
I20260812 06:18:38.505894  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000017 (ops 82-86)
I20260812 06:18:38.505926  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000018 (ops 87-90)
I20260812 06:18:38.505956  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000019 (ops 91-95)
I20260812 06:18:38.505986  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000020 (ops 96-100)
I20260812 06:18:38.506017  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000021 (ops 101-105)
I20260812 06:18:38.506047  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000022 (ops 106-110)
I20260812 06:18:38.506076  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000023 (ops 111-115)
I20260812 06:18:38.506106  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000024 (ops 116-120)
I20260812 06:18:38.506137  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000025 (ops 121-124)
I20260812 06:18:38.527757  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: LogGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.022s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:18:38.528141  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=3.181125
I20260812 06:18:38.551611  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.023s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4996,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:18:38.552037  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:38.561322  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3299,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:38.561816  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:38.794296  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.232s	user 0.140s	sys 0.090s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37123149,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":952,"lbm_read_time_us":17655,"lbm_reads_lt_1ms":874,"lbm_write_time_us":37841,"lbm_writes_lt_1ms":843,"mutex_wait_us":76,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4480,"thread_start_us":112,"threads_started":1,"update_count":4000}
I20260812 06:18:38.794809  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=18.063937
I20260812 06:18:38.844720  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.050s	user 0.024s	sys 0.024s Metrics: {"bytes_written":20512321,"delete_count":0,"lbm_write_time_us":21801,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:38.845309  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:38.870873  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.025s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5065,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.871419  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:38.887040  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5766,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:38.887652  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:39.068967  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.181s	user 0.132s	sys 0.048s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020634,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":353,"lbm_read_time_us":11848,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37845,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3500}
I20260812 06:18:39.069629  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:39.121088  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.051s	user 0.024s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20034,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.121907  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82): 462 bytes on disk
I20260812 06:18:39.122411  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:18:39.123350  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:39.147183  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.024s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4996,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.147658  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:39.157591  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3726,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.158023  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:39.321013  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.163s	user 0.124s	sys 0.035s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918215,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":323,"lbm_read_time_us":11795,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30835,"lbm_writes_lt_1ms":643,"mutex_wait_us":93,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":3000}
I20260812 06:18:39.321561  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:39.374799  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.053s	user 0.024s	sys 0.025s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22395,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.375433  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:39.391393  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.016s	user 0.007s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":500}
I20260812 06:18:39.392057  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:39.549226  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.157s	user 0.107s	sys 0.035s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815680,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":266,"lbm_read_time_us":9341,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28042,"lbm_writes_lt_1ms":543,"mutex_wait_us":21,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:39.549888  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:39.604107  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.054s	user 0.027s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19592,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.604704  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:39.615072  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3665,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:39.615619  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:39.791216  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.175s	user 0.117s	sys 0.058s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":202,"lbm_read_time_us":12752,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28663,"lbm_writes_lt_1ms":543,"mutex_wait_us":48,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:18:39.791796  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=14.095187
I20260812 06:18:39.834422  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.042s	user 0.019s	sys 0.019s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17792,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:39.834941  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushMRSOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:39.888296  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushMRSOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.053s	user 0.031s	sys 0.003s Metrics: {"bytes_written":1234475,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1416,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1757,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:39.889142  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling LogGCOp(88570c24cf0542bd9870d9052af98f82): free 121006674 bytes of WAL
I20260812 06:18:39.889376  7878 log_reader.cc:385] T 88570c24cf0542bd9870d9052af98f82: removed 12 log segments from log reader
I20260812 06:18:39.889429  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000026 (ops 125-129)
I20260812 06:18:39.889467  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000027 (ops 130-134)
I20260812 06:18:39.889500  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000028 (ops 135-139)
I20260812 06:18:39.889533  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000029 (ops 140-144)
I20260812 06:18:39.889565  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000030 (ops 145-149)
I20260812 06:18:39.889595  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000031 (ops 150-154)
I20260812 06:18:39.889626  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000032 (ops 155-158)
I20260812 06:18:39.889654  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000033 (ops 159-163)
I20260812 06:18:39.889683  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000034 (ops 164-168)
I20260812 06:18:39.889712  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000035 (ops 169-173)
I20260812 06:18:39.889741  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000036 (ops 174-178)
I20260812 06:18:39.889771  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000037 (ops 179-183)
I20260812 06:18:39.910691  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: LogGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:18:39.911224  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=7.149875
I20260812 06:18:39.930586  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":8615323,"delete_count":0,"lbm_write_time_us":7783,"lbm_writes_lt_1ms":213,"reinsert_count":0,"update_count":1050}
I20260812 06:18:39.931094  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling LogGCOp(88570c24cf0542bd9870d9052af98f82): free 12017954 bytes of WAL
I20260812 06:18:39.931524  7878 log_reader.cc:385] T 88570c24cf0542bd9870d9052af98f82: removed 1 log segments from log reader
I20260812 06:18:39.931579  7878 log.cc:1079] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: Deleting log segment in path: /tmp/dist-test-taskxaSlj9/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515510128730-7398-0/minicluster-data/ts-0-root/wals/88570c24cf0542bd9870d9052af98f82/wal-000000038 (ops 184-188)
I20260812 06:18:39.933481  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: LogGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:18:39.933816  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:39.944525  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:39.945083  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:40.165093  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.219s	user 0.165s	sys 0.046s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020620,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":463,"lbm_read_time_us":15806,"lbm_reads_lt_1ms":769,"lbm_write_time_us":38707,"lbm_writes_lt_1ms":743,"mutex_wait_us":49,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":16384,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:18:40.165678  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82): 473 bytes on disk
I20260812 06:18:40.166568  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: UndoDeltaBlockGCOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:18:40.167182  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=18.063937
I20260812 06:18:40.219659  7398 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.646s	user 1.705s	sys 0.160s
I20260812 06:18:40.221824  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.054s	user 0.041s	sys 0.012s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25454,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:18:40.222342  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82): perf score=2.188937
I20260812 06:18:40.238123  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: FlushDeltaMemStoresOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.016s	user 0.011s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6477,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:40.238687  7987 maintenance_manager.cc:419] P e56e9f437c724dfe9d996866da2e1218: Scheduling MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82): perf score=1.000000
I20260812 06:18:40.255618  7398 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:18:40.256085  7398 tablet_server.cc:179] TabletServer@127.7.57.129:0 shutting down...
I20260812 06:18:40.380920  7878 maintenance_manager.cc:643] P e56e9f437c724dfe9d996866da2e1218: MajorDeltaCompactionOp(88570c24cf0542bd9870d9052af98f82) complete. Timing: real 0.142s	user 0.095s	sys 0.047s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4303385,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614712,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":426,"lbm_read_time_us":9852,"lbm_reads_lt_1ms":618,"lbm_write_time_us":26124,"lbm_writes_lt_1ms":643,"mutex_wait_us":57,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":3000}
I20260812 06:18:40.381705  7398 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:40.381956  7398 tablet_replica.cc:333] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218: stopping tablet replica
I20260812 06:18:40.382074  7398 raft_consensus.cc:2243] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.382225  7398 raft_consensus.cc:2272] T 88570c24cf0542bd9870d9052af98f82 P e56e9f437c724dfe9d996866da2e1218 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.396548  7398 tablet_server.cc:196] TabletServer@127.7.57.129:0 shutdown complete.
I20260812 06:18:40.432701  7398 master.cc:562] Master@127.7.57.190:36481 shutting down...
I20260812 06:18:40.435847  7398 raft_consensus.cc:2243] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:40.436040  7398 raft_consensus.cc:2272] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:40.436110  7398 tablet_replica.cc:333] T 00000000000000000000000000000000 P bff5a2b096da4c0da6091ec708e0e8f9: stopping tablet replica
I20260812 06:18:40.448216  7398 master.cc:584] Master@127.7.57.190:36481 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5144 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10381 ms total)

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