[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:16:38.465308 22118 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.153.190:33663
I20260812 06:16:38.466209 22118 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:16:38.466743 22118 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.472577 22130 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.472622 22118 server_base.cc:1061] running on GCE node
W20260812 06:16:38.472592 22134 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.472898 22128 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.473348 22118 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.473438 22118 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.473477 22118 hybrid_clock.cc:648] HybridClock initialized: now 1786515398473475 us; error 0 us; skew 500 ppm
I20260812 06:16:38.478291 22118 webserver.cc:533] Webserver started at http://127.21.153.190:42377/ using document root <none> and password file <none>
I20260812 06:16:38.478760 22118 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.478818 22118 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.479027 22118 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.480520 22118 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/master-0-root/instance:
uuid: "4abe87c46fae4b539b07b62925b28427"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-q9h9"
I20260812 06:16:38.483673 22118 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:16:38.485481 22150 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.486413 22118 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:16:38.486511 22118 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/master-0-root
uuid: "4abe87c46fae4b539b07b62925b28427"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-q9h9"
I20260812 06:16:38.486590 22118 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.500921 22118 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.501436 22118 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:16:38.501570 22118 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.508481 22267 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.153.190:33663 every 8 connection(s)
I20260812 06:16:38.508486 22118 rpc_server.cc:307] RPC server started. Bound to: 127.21.153.190:33663
I20260812 06:16:38.510517 22268 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.515583 22268 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: Bootstrap starting.
I20260812 06:16:38.517726 22268 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.518558 22268 log.cc:826] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: Log is configured to *not* fsync() on all Append() calls
I20260812 06:16:38.520009 22268 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: No bootstrap required, opened a new log
I20260812 06:16:38.522542 22268 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER }
I20260812 06:16:38.522682 22268 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.522755 22268 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4abe87c46fae4b539b07b62925b28427, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.523365 22268 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [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: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER }
I20260812 06:16:38.523504 22268 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.523566 22268 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.523679 22268 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.524344 22268 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER }
I20260812 06:16:38.524745 22268 leader_election.cc:304] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [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: 4abe87c46fae4b539b07b62925b28427; no voters: 
I20260812 06:16:38.525012 22268 leader_election.cc:290] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.525158 22274 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.525364 22274 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 1 LEADER]: Becoming Leader. State: Replica: 4abe87c46fae4b539b07b62925b28427, State: Running, Role: LEADER
I20260812 06:16:38.525707 22274 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [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: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER }
I20260812 06:16:38.525832 22268 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:38.527501 22279 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4abe87c46fae4b539b07b62925b28427. Latest consensus state: current_term: 1 leader_uuid: "4abe87c46fae4b539b07b62925b28427" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER } }
I20260812 06:16:38.527621 22279 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.527925 22303 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:38.527899 22275 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4abe87c46fae4b539b07b62925b28427" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4abe87c46fae4b539b07b62925b28427" member_type: VOTER } }
I20260812 06:16:38.528013 22118 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:38.528035 22275 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:38.530148 22303 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:38.534358 22303 catalog_manager.cc:1383] Generated new cluster ID: 937a7709dcd042c7bdb059eba44f66b0
I20260812 06:16:38.534418 22303 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:38.551091 22303 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:38.551790 22303 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:38.562319 22303 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: Generated new TSK 0
I20260812 06:16:38.562806 22303 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:38.592589 22118 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:38.595211 22317 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:38.595302 22319 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.595418 22118 server_base.cc:1061] running on GCE node
W20260812 06:16:38.595486 22321 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:38.595680 22118 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:38.595729 22118 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:38.595752 22118 hybrid_clock.cc:648] HybridClock initialized: now 1786515398595750 us; error 0 us; skew 500 ppm
I20260812 06:16:38.596565 22118 webserver.cc:533] Webserver started at http://127.21.153.129:41965/ using document root <none> and password file <none>
I20260812 06:16:38.596725 22118 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:38.596774 22118 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:38.596848 22118 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:38.597178 22118 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/instance:
uuid: "856db894aae84449b00f74c905f3e206"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-q9h9"
I20260812 06:16:38.598642 22118 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:38.599550 22335 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.599782 22118 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:38.599844 22118 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root
uuid: "856db894aae84449b00f74c905f3e206"
format_stamp: "Formatted at 2026-08-12 06:16:38 on dist-test-slave-q9h9"
I20260812 06:16:38.599907 22118 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:38.616480 22118 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:38.616850 22118 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:38.617238 22118 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:38.618042 22118 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:38.618104 22118 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.618151 22118 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:38.618182 22118 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:38.623974 22118 rpc_server.cc:307] RPC server started. Bound to: 127.21.153.129:36213
I20260812 06:16:38.624156 22449 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.153.129:36213 every 8 connection(s)
I20260812 06:16:38.636341 22453 heartbeater.cc:344] Connected to a master server at 127.21.153.190:33663
I20260812 06:16:38.636547 22453 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:38.636955 22453 heartbeater.cc:507] Master 127.21.153.190:33663 requested a full tablet report, sending...
I20260812 06:16:38.638423 22188 ts_manager.cc:194] Registered new tserver with Master: 856db894aae84449b00f74c905f3e206 (127.21.153.129:36213)
I20260812 06:16:38.638904 22118 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01433649s
I20260812 06:16:38.639896 22188 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:57442
I20260812 06:16:38.647188 22188 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:57446:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:38.670648 22392 tablet_service.cc:1511] Processing CreateTablet for tablet b9affcc27e754c8facad8a73b1f51bb2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=af638ed9948e4163b781333005f26357]), partition=
I20260812 06:16:38.671136 22392 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b9affcc27e754c8facad8a73b1f51bb2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:38.673830 22473 tablet_bootstrap.cc:492] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Bootstrap starting.
I20260812 06:16:38.675159 22473 tablet_bootstrap.cc:654] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:38.676352 22473 tablet_bootstrap.cc:492] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: No bootstrap required, opened a new log
I20260812 06:16:38.676456 22473 ts_tablet_manager.cc:1403] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:16:38.676934 22473 raft_consensus.cc:359] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "856db894aae84449b00f74c905f3e206" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 36213 } }
I20260812 06:16:38.677034 22473 raft_consensus.cc:385] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:38.677057 22473 raft_consensus.cc:740] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 856db894aae84449b00f74c905f3e206, State: Initialized, Role: FOLLOWER
I20260812 06:16:38.677189 22473 consensus_queue.cc:260] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [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: "856db894aae84449b00f74c905f3e206" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 36213 } }
I20260812 06:16:38.677250 22473 raft_consensus.cc:399] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:38.677276 22473 raft_consensus.cc:493] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:38.677307 22473 raft_consensus.cc:3060] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:38.678066 22473 raft_consensus.cc:515] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "856db894aae84449b00f74c905f3e206" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 36213 } }
I20260812 06:16:38.678187 22473 leader_election.cc:304] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [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: 856db894aae84449b00f74c905f3e206; no voters: 
I20260812 06:16:38.679086 22473 leader_election.cc:290] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:38.679212 22477 raft_consensus.cc:2804] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:38.679405 22477 raft_consensus.cc:697] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 1 LEADER]: Becoming Leader. State: Replica: 856db894aae84449b00f74c905f3e206, State: Running, Role: LEADER
I20260812 06:16:38.679410 22473 ts_tablet_manager.cc:1434] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:16:38.679585 22477 consensus_queue.cc:237] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [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: "856db894aae84449b00f74c905f3e206" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 36213 } }
I20260812 06:16:38.679998 22453 heartbeater.cc:499] Master 127.21.153.190:33663 was elected leader, sending a full tablet report...
I20260812 06:16:38.682657 22188 catalog_manager.cc:5719] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 reported cstate change: term changed from 0 to 1, leader changed from <none> to 856db894aae84449b00f74c905f3e206 (127.21.153.129). New cstate: current_term: 1 leader_uuid: "856db894aae84449b00f74c905f3e206" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "856db894aae84449b00f74c905f3e206" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 36213 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:38.747185 22118 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.059s	user 0.023s	sys 0.005s
I20260812 06:16:38.874971 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=19.054940
I20260812 06:16:39.025727 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.150s	user 0.104s	sys 0.044s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":181,"delete_count":0,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":719,"drs_written":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38497,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":101,"threads_started":1,"update_count":1500}
I20260812 06:16:39.026744 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:39.138322 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.111s	user 0.091s	sys 0.017s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":646,"lbm_read_time_us":6536,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19629,"lbm_writes_lt_1ms":343,"peak_mem_usage":38262756,"reinsert_count":0,"thread_start_us":346,"threads_started":5,"update_count":1500}
I20260812 06:16:39.138849 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling LogGCOp(b9affcc27e754c8facad8a73b1f51bb2): free 20743880 bytes of WAL
I20260812 06:16:39.139168 22352 log_reader.cc:385] T b9affcc27e754c8facad8a73b1f51bb2: removed 2 log segments from log reader
I20260812 06:16:39.139240 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000001 (ops 1-6)
I20260812 06:16:39.139300 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000002 (ops 7-11)
I20260812 06:16:39.143937 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: LogGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.005s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:39.144284 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:39.187593 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.043s	user 0.020s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17196,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.188136 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:39.199230 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4200,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.199755 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2): 16411396 bytes on disk
I20260812 06:16:39.200371 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2) 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:16:39.200922 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:39.333226 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.132s	user 0.092s	sys 0.040s 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":146,"lbm_read_time_us":11052,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23244,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4096,"update_count":2000}
I20260812 06:16:39.333766 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:39.372435 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.039s	user 0.024s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16140,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.372871 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:39.479043 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.106s	user 0.102s	sys 0.004s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":592,"lbm_read_time_us":7063,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17515,"lbm_writes_lt_1ms":343,"mutex_wait_us":34,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":1500}
I20260812 06:16:39.479477 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:39.513866 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.034s	user 0.020s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13224,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.514315 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:39.529289 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.015s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5626,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.529735 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:39.646961 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.117s	user 0.077s	sys 0.040s 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":859,"lbm_read_time_us":8255,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21733,"lbm_writes_lt_1ms":443,"mutex_wait_us":300,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:39.647433 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:39.688841 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.041s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14420,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.689366 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:39.699196 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3858,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.699681 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:39.819802 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.120s	user 0.100s	sys 0.020s 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":643,"lbm_read_time_us":8388,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23270,"lbm_writes_lt_1ms":443,"mutex_wait_us":310,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:16:39.822458 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:39.863277 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.040s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12332,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:39.863720 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:39.873418 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3809,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:39.873745 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.002959 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.129s	user 0.088s	sys 0.039s 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":1265,"lbm_read_time_us":10507,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19868,"lbm_writes_lt_1ms":443,"mutex_wait_us":362,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.003497 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:40.046132 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.042s	user 0.028s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13481,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.046617 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.056398 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.056965 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.177989 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.121s	user 0.096s	sys 0.024s 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":673,"lbm_read_time_us":9554,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22843,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:16:40.178480 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:40.213757 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.035s	user 0.025s	sys 0.007s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":15488,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:40.214254 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.232156 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.018s	user 0.012s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5172,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.232664 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.280411 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.048s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1079,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2099,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:40.281232 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling LogGCOp(b9affcc27e754c8facad8a73b1f51bb2): free 124710294 bytes of WAL
I20260812 06:16:40.281446 22352 log_reader.cc:385] T b9affcc27e754c8facad8a73b1f51bb2: removed 12 log segments from log reader
I20260812 06:16:40.281494 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000003 (ops 12-16)
I20260812 06:16:40.281524 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000004 (ops 17-21)
I20260812 06:16:40.281556 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000005 (ops 22-26)
I20260812 06:16:40.281581 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000006 (ops 27-31)
I20260812 06:16:40.281613 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000007 (ops 32-36)
I20260812 06:16:40.281646 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000008 (ops 37-41)
I20260812 06:16:40.281688 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000009 (ops 42-46)
I20260812 06:16:40.281711 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000010 (ops 47-51)
I20260812 06:16:40.281742 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000011 (ops 52-56)
I20260812 06:16:40.281774 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000012 (ops 57-61)
I20260812 06:16:40.281806 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000013 (ops 62-66)
I20260812 06:16:40.281838 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000014 (ops 67-71)
I20260812 06:16:40.303779 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: LogGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:40.304150 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=6.157687
I20260812 06:16:40.322007 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.018s	user 0.007s	sys 0.009s Metrics: {"bytes_written":8205080,"delete_count":0,"lbm_write_time_us":7292,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:16:40.322393 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2): 483 bytes on disk
I20260812 06:16:40.322747 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:40.323235 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.335076 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.335500 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.520061 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.184s	user 0.122s	sys 0.061s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979753,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":208,"lbm_read_time_us":11890,"lbm_reads_lt_1ms":766,"lbm_write_time_us":38300,"lbm_writes_lt_1ms":743,"mutex_wait_us":64,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":69,"threads_started":1,"update_count":3500}
I20260812 06:16:40.520583 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=15.087375
I20260812 06:16:40.559969 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.039s	user 0.029s	sys 0.007s Metrics: {"bytes_written":16573999,"delete_count":0,"lbm_write_time_us":16593,"lbm_writes_lt_1ms":407,"reinsert_count":0,"update_count":2020}
I20260812 06:16:40.560575 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.585265 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":5001,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:16:40.585726 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.595762 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:40.596323 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.746116 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.150s	user 0.110s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877217,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":297,"lbm_read_time_us":10688,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31150,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:16:40.747048 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:40.788329 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.041s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18355,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.788885 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:40.808017 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.019s	user 0.000s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5328,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:16:40.808487 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:40.949672 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.141s	user 0.103s	sys 0.038s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":298,"lbm_read_time_us":9082,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26922,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:40.950322 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:40.990279 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.040s	user 0.031s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:40.991490 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:41.130498 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.139s	user 0.086s	sys 0.047s 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":282,"lbm_read_time_us":10744,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22002,"lbm_writes_lt_1ms":443,"mutex_wait_us":19,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2000}
I20260812 06:16:41.131022 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:41.182531 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.051s	user 0.029s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24168,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.183065 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:41.208835 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.026s	user 0.010s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4878,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.210148 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:41.367933 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.158s	user 0.112s	sys 0.046s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":232,"lbm_read_time_us":12720,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26811,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:16:41.368670 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:41.409561 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.041s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":17037,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:41.410043 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:41.419715 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.420166 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:41.554958 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.135s	user 0.098s	sys 0.036s 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":334,"lbm_read_time_us":9555,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27356,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":699136,"update_count":2500}
I20260812 06:16:41.555677 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:41.583743 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.028s	user 0.021s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12002,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:41.584312 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:41.596225 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4073,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:41.596689 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:41.629254 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":198,"dirs.run_wall_time_us":1099,"drs_written":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1896,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:41.630160 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling LogGCOp(b9affcc27e754c8facad8a73b1f51bb2): free 128867476 bytes of WAL
I20260812 06:16:41.630376 22352 log_reader.cc:385] T b9affcc27e754c8facad8a73b1f51bb2: removed 13 log segments from log reader
I20260812 06:16:41.630435 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000015 (ops 72-76)
I20260812 06:16:41.630505 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000016 (ops 77-81)
I20260812 06:16:41.630539 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000017 (ops 82-86)
I20260812 06:16:41.630569 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000018 (ops 87-90)
I20260812 06:16:41.630601 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000019 (ops 91-95)
I20260812 06:16:41.630632 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000020 (ops 96-100)
I20260812 06:16:41.630662 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000021 (ops 101-104)
I20260812 06:16:41.630707 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000022 (ops 105-109)
I20260812 06:16:41.630765 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000023 (ops 110-114)
I20260812 06:16:41.630801 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000024 (ops 115-119)
I20260812 06:16:41.630824 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000025 (ops 120-124)
I20260812 06:16:41.630853 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000026 (ops 125-128)
I20260812 06:16:41.630916 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000027 (ops 129-133)
I20260812 06:16:41.656385 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: LogGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:16:41.656759 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2): 482 bytes on disk
I20260812 06:16:41.657163 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:16:41.657655 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=6.157687
I20260812 06:16:41.677632 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.020s	user 0.005s	sys 0.011s Metrics: {"bytes_written":7917910,"delete_count":0,"lbm_write_time_us":7666,"lbm_writes_lt_1ms":196,"reinsert_count":0,"update_count":965}
I20260812 06:16:41.678087 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:41.866389 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.188s	user 0.133s	sys 0.048s Metrics: {"cfile_cache_miss":626,"cfile_cache_miss_bytes":28590053,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1115,"dirs.run_cpu_time_us":986,"dirs.run_wall_time_us":6131,"lbm_read_time_us":12813,"lbm_reads_lt_1ms":658,"lbm_write_time_us":33871,"lbm_writes_lt_1ms":636,"mutex_wait_us":262,"peak_mem_usage":74214843,"reinsert_count":0,"spinlock_wait_cycles":2688,"thread_start_us":184,"threads_started":1,"update_count":2965}
I20260812 06:16:41.867018 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=15.087375
I20260812 06:16:41.926756 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.059s	user 0.030s	sys 0.019s Metrics: {"bytes_written":17107318,"delete_count":0,"lbm_write_time_us":24494,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":419,"reinsert_count":0,"update_count":2085}
I20260812 06:16:41.927251 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=6.157687
I20260812 06:16:41.952574 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.025s	user 0.005s	sys 0.012s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7943,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:41.953051 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:42.137809 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.185s	user 0.117s	sys 0.062s Metrics: {"cfile_cache_miss":639,"cfile_cache_miss_bytes":29164276,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":867,"lbm_read_time_us":14223,"lbm_reads_lt_1ms":675,"lbm_write_time_us":31051,"lbm_writes_lt_1ms":650,"mutex_wait_us":295,"peak_mem_usage":75829717,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":3035}
I20260812 06:16:42.138540 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=15.087375
I20260812 06:16:42.201488 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.063s	user 0.028s	sys 0.023s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":18398,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:42.201910 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=6.157687
I20260812 06:16:42.219411 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.017s	user 0.010s	sys 0.006s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7279,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:42.219980 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:42.398685 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.178s	user 0.109s	sys 0.069s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877101,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":541,"lbm_read_time_us":12466,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31894,"lbm_writes_lt_1ms":643,"mutex_wait_us":35,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":3000}
I20260812 06:16:42.399190 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:42.456529 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.057s	user 0.033s	sys 0.011s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":20817,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.457093 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:42.466949 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3746,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.467423 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:42.632856 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.165s	user 0.117s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":115,"lbm_read_time_us":11935,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31705,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:16:42.633399 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=14.095187
I20260812 06:16:42.686365 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.053s	user 0.025s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19437,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:42.686884 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:42.697306 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.697700 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:42.861593 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.164s	user 0.117s	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":113,"lbm_read_time_us":12100,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28362,"lbm_writes_lt_1ms":543,"mutex_wait_us":65,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2500}
I20260812 06:16:42.862231 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=11.118625
I20260812 06:16:42.901587 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.039s	user 0.023s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":16567,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:16:42.902110 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:42.929155 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.027s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4362,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:42.929629 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:42.938621 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3440,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:42.939082 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:42.971791 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushMRSOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.033s	user 0.022s	sys 0.004s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1128,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1326,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:42.972505 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling LogGCOp(b9affcc27e754c8facad8a73b1f51bb2): free 121006705 bytes of WAL
I20260812 06:16:42.972741 22352 log_reader.cc:385] T b9affcc27e754c8facad8a73b1f51bb2: removed 12 log segments from log reader
I20260812 06:16:42.972803 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000028 (ops 134-138)
I20260812 06:16:42.972847 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000029 (ops 139-143)
I20260812 06:16:42.972882 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000030 (ops 144-148)
I20260812 06:16:42.972906 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000031 (ops 149-153)
I20260812 06:16:42.972934 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000032 (ops 154-158)
I20260812 06:16:42.972959 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000033 (ops 159-163)
I20260812 06:16:42.972983 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000034 (ops 164-168)
I20260812 06:16:42.973008 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000035 (ops 169-173)
I20260812 06:16:42.973037 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000036 (ops 174-178)
I20260812 06:16:42.973067 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000037 (ops 179-182)
I20260812 06:16:42.973091 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000038 (ops 183-187)
I20260812 06:16:42.973116 22352 log.cc:1079] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/b9affcc27e754c8facad8a73b1f51bb2/wal-000000039 (ops 188-192)
I20260812 06:16:43.001191 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: LogGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.029s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:16:43.001571 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=3.181125
I20260812 06:16:43.016811 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.015s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:43.017249 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=2.188937
I20260812 06:16:43.030298 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.013s	user 0.009s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4881,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.030812 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=1.000000
I20260812 06:16:43.161602 22118 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.414s	user 1.590s	sys 0.123s
I20260812 06:16:43.257015 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: MajorDeltaCompactionOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.226s	user 0.146s	sys 0.080s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979851,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":310,"lbm_read_time_us":16029,"lbm_reads_lt_1ms":771,"lbm_write_time_us":38859,"lbm_writes_lt_1ms":743,"mutex_wait_us":90,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":71,"threads_started":1,"update_count":3500}
I20260812 06:16:43.258361 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2): 462 bytes on disk
I20260812 06:16:43.259531 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: UndoDeltaBlockGCOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.260162 22454 maintenance_manager.cc:419] P 856db894aae84449b00f74c905f3e206: Scheduling FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2): perf score=10.126437
I20260812 06:16:43.274510 22118 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.003s	sys 0.000s
I20260812 06:16:43.275087 22118 tablet_server.cc:179] TabletServer@127.21.153.129:0 shutting down...
I20260812 06:16:43.293864 22352 maintenance_manager.cc:643] P 856db894aae84449b00f74c905f3e206: FlushDeltaMemStoresOp(b9affcc27e754c8facad8a73b1f51bb2) complete. Timing: real 0.034s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14814,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:16:43.294355 22118 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:43.294725 22118 tablet_replica.cc:333] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206: stopping tablet replica
I20260812 06:16:43.294950 22118 raft_consensus.cc:2243] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.295161 22118 raft_consensus.cc:2272] T b9affcc27e754c8facad8a73b1f51bb2 P 856db894aae84449b00f74c905f3e206 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.310079 22118 tablet_server.cc:196] TabletServer@127.21.153.129:0 shutdown complete.
I20260812 06:16:43.315846 22118 master.cc:562] Master@127.21.153.190:33663 shutting down...
I20260812 06:16:43.318956 22118 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:43.319079 22118 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:43.319128 22118 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4abe87c46fae4b539b07b62925b28427: stopping tablet replica
I20260812 06:16:43.330924 22118 master.cc:584] Master@127.21.153.190:33663 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (4940 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:16:43.405371 22118 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.21.153.190:39683
I20260812 06:16:43.405686 22118 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:43.407461 22510 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:43.407578 22508 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:43.407652 22507 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:43.407665 22118 server_base.cc:1061] running on GCE node
I20260812 06:16:43.407833 22118 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:43.407869 22118 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:43.407883 22118 hybrid_clock.cc:648] HybridClock initialized: now 1786515403407884 us; error 0 us; skew 500 ppm
I20260812 06:16:43.408586 22118 webserver.cc:533] Webserver started at http://127.21.153.190:42649/ using document root <none> and password file <none>
I20260812 06:16:43.408707 22118 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:43.408743 22118 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:43.408797 22118 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:43.409111 22118 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/master-0-root/instance:
uuid: "1bd79e20abce4edda749275208082c71"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-q9h9"
I20260812 06:16:43.410532 22118 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:16:43.411371 22519 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.411623 22118 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:16:43.411695 22118 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/master-0-root
uuid: "1bd79e20abce4edda749275208082c71"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-q9h9"
I20260812 06:16:43.411762 22118 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:43.417189 22118 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:43.417466 22118 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:43.421289 22118 rpc_server.cc:307] RPC server started. Bound to: 127.21.153.190:39683
I20260812 06:16:43.433893 22607 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.153.190:39683 every 8 connection(s)
I20260812 06:16:43.434309 22608 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:43.435972 22608 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71: Bootstrap starting.
I20260812 06:16:43.436683 22608 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:43.437600 22608 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71: No bootstrap required, opened a new log
I20260812 06:16:43.437983 22608 raft_consensus.cc:359] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1bd79e20abce4edda749275208082c71" member_type: VOTER }
I20260812 06:16:43.438099 22608 raft_consensus.cc:385] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:43.438143 22608 raft_consensus.cc:740] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1bd79e20abce4edda749275208082c71, State: Initialized, Role: FOLLOWER
I20260812 06:16:43.438277 22608 consensus_queue.cc:260] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [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: "1bd79e20abce4edda749275208082c71" member_type: VOTER }
I20260812 06:16:43.438347 22608 raft_consensus.cc:399] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:43.438386 22608 raft_consensus.cc:493] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:43.438433 22608 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:43.439074 22608 raft_consensus.cc:515] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1bd79e20abce4edda749275208082c71" member_type: VOTER }
I20260812 06:16:43.439203 22608 leader_election.cc:304] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [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: 1bd79e20abce4edda749275208082c71; no voters: 
I20260812 06:16:43.439361 22608 leader_election.cc:290] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:43.439483 22612 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:43.439677 22612 raft_consensus.cc:697] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 1 LEADER]: Becoming Leader. State: Replica: 1bd79e20abce4edda749275208082c71, State: Running, Role: LEADER
I20260812 06:16:43.439777 22608 sys_catalog.cc:565] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:16:43.439832 22612 consensus_queue.cc:237] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [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: "1bd79e20abce4edda749275208082c71" member_type: VOTER }
I20260812 06:16:43.440250 22616 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 1bd79e20abce4edda749275208082c71. Latest consensus state: current_term: 1 leader_uuid: "1bd79e20abce4edda749275208082c71" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1bd79e20abce4edda749275208082c71" member_type: VOTER } }
I20260812 06:16:43.440237 22614 sys_catalog.cc:455] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "1bd79e20abce4edda749275208082c71" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1bd79e20abce4edda749275208082c71" member_type: VOTER } }
I20260812 06:16:43.440354 22614 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:43.440344 22616 sys_catalog.cc:458] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [sys.catalog]: This master's current role is: LEADER
I20260812 06:16:43.440623 22623 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:16:43.441407 22623 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:16:43.441545 22118 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:16:43.443147 22623 catalog_manager.cc:1383] Generated new cluster ID: 8153d65ceaa04dcdb25644cc645d3b16
I20260812 06:16:43.443207 22623 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:16:43.448745 22623 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:16:43.449259 22623 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:16:43.456070 22623 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71: Generated new TSK 0
I20260812 06:16:43.456208 22623 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:16:43.457573 22118 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:16:43.459151 22653 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:43.459201 22655 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:16:43.459096 22650 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:16:43.459304 22118 server_base.cc:1061] running on GCE node
I20260812 06:16:43.459499 22118 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:16:43.459543 22118 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:16:43.459558 22118 hybrid_clock.cc:648] HybridClock initialized: now 1786515403459557 us; error 0 us; skew 500 ppm
I20260812 06:16:43.460292 22118 webserver.cc:533] Webserver started at http://127.21.153.129:39533/ using document root <none> and password file <none>
I20260812 06:16:43.460408 22118 fs_manager.cc:362] Metadata directory not provided
I20260812 06:16:43.460445 22118 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:16:43.460494 22118 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:16:43.460793 22118 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/instance:
uuid: "952fadc8ab9c467295db623f42bf6998"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-q9h9"
I20260812 06:16:43.462090 22118 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:16:43.462905 22664 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.463106 22118 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:16:43.463168 22118 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root
uuid: "952fadc8ab9c467295db623f42bf6998"
format_stamp: "Formatted at 2026-08-12 06:16:43 on dist-test-slave-q9h9"
I20260812 06:16:43.463229 22118 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:16:43.468864 22118 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:16:43.469125 22118 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:16:43.469364 22118 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:16:43.469743 22118 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:16:43.469787 22118 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.469826 22118 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:16:43.469854 22118 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:16:43.473575 22118 rpc_server.cc:307] RPC server started. Bound to: 127.21.153.129:33793
I20260812 06:16:43.473608 22786 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.21.153.129:33793 every 8 connection(s)
I20260812 06:16:43.478037 22787 heartbeater.cc:344] Connected to a master server at 127.21.153.190:39683
I20260812 06:16:43.478156 22787 heartbeater.cc:461] Registering TS with master...
I20260812 06:16:43.478346 22787 heartbeater.cc:507] Master 127.21.153.190:39683 requested a full tablet report, sending...
I20260812 06:16:43.478919 22557 ts_manager.cc:194] Registered new tserver with Master: 952fadc8ab9c467295db623f42bf6998 (127.21.153.129:33793)
I20260812 06:16:43.479485 22118 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.005532136s
I20260812 06:16:43.479564 22557 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50436
I20260812 06:16:43.485724 22557 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50450:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:16:43.493356 22712 tablet_service.cc:1511] Processing CreateTablet for tablet c44a61b250404b9b93444cfc235259cd (DEFAULT_TABLE table=heavy-update-compaction-test [id=f9b3eeb46f0a455ba453d17157562c6e]), partition=
I20260812 06:16:43.493574 22712 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet c44a61b250404b9b93444cfc235259cd. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:16:43.495347 22815 tablet_bootstrap.cc:492] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Bootstrap starting.
I20260812 06:16:43.496253 22815 tablet_bootstrap.cc:654] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Neither blocks nor log segments found. Creating new log.
I20260812 06:16:43.497221 22815 tablet_bootstrap.cc:492] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: No bootstrap required, opened a new log
I20260812 06:16:43.497292 22815 ts_tablet_manager.cc:1403] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:16:43.497679 22815 raft_consensus.cc:359] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "952fadc8ab9c467295db623f42bf6998" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 33793 } }
I20260812 06:16:43.497756 22815 raft_consensus.cc:385] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:16:43.497786 22815 raft_consensus.cc:740] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 952fadc8ab9c467295db623f42bf6998, State: Initialized, Role: FOLLOWER
I20260812 06:16:43.497927 22815 consensus_queue.cc:260] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [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: "952fadc8ab9c467295db623f42bf6998" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 33793 } }
I20260812 06:16:43.497998 22815 raft_consensus.cc:399] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:16:43.498059 22815 raft_consensus.cc:493] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:16:43.498108 22815 raft_consensus.cc:3060] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:16:43.498832 22815 raft_consensus.cc:515] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "952fadc8ab9c467295db623f42bf6998" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 33793 } }
I20260812 06:16:43.498962 22815 leader_election.cc:304] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [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: 952fadc8ab9c467295db623f42bf6998; no voters: 
I20260812 06:16:43.499159 22815 leader_election.cc:290] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:16:43.499271 22820 raft_consensus.cc:2804] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:16:43.499486 22820 raft_consensus.cc:697] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 1 LEADER]: Becoming Leader. State: Replica: 952fadc8ab9c467295db623f42bf6998, State: Running, Role: LEADER
I20260812 06:16:43.499460 22815 ts_tablet_manager.cc:1434] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:16:43.499513 22787 heartbeater.cc:499] Master 127.21.153.190:39683 was elected leader, sending a full tablet report...
I20260812 06:16:43.499656 22820 consensus_queue.cc:237] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [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: "952fadc8ab9c467295db623f42bf6998" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 33793 } }
I20260812 06:16:43.500886 22557 catalog_manager.cc:5719] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 reported cstate change: term changed from 0 to 1, leader changed from <none> to 952fadc8ab9c467295db623f42bf6998 (127.21.153.129). New cstate: current_term: 1 leader_uuid: "952fadc8ab9c467295db623f42bf6998" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "952fadc8ab9c467295db623f42bf6998" member_type: VOTER last_known_addr { host: "127.21.153.129" port: 33793 } health_report { overall_health: HEALTHY } } }
I20260812 06:16:43.553679 22118 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.013s	sys 0.008s
I20260812 06:16:43.724457 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushMRSOp(c44a61b250404b9b93444cfc235259cd): perf score=23.023690
I20260812 06:16:43.870635 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushMRSOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.146s	user 0.104s	sys 0.040s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":837,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":39261,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:16:43.871346 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling LogGCOp(c44a61b250404b9b93444cfc235259cd): free 20743880 bytes of WAL
I20260812 06:16:43.871565 22671 log_reader.cc:385] T c44a61b250404b9b93444cfc235259cd: removed 2 log segments from log reader
I20260812 06:16:43.871616 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000001 (ops 1-6)
I20260812 06:16:43.871656 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000002 (ops 7-11)
I20260812 06:16:43.875253 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: LogGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:16:43.875555 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=3.181125
I20260812 06:16:43.895083 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.019s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4997,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:43.895499 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd): 20513813 bytes on disk
I20260812 06:16:43.895905 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4}
I20260812 06:16:43.896320 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:43.905012 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3321,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:43.905426 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:44.058434 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.153s	user 0.118s	sys 0.028s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":621,"lbm_read_time_us":12645,"lbm_reads_lt_1ms":569,"lbm_write_time_us":25389,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":316,"threads_started":5,"update_count":2500}
I20260812 06:16:44.059046 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:44.103681 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.044s	user 0.015s	sys 0.024s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":17615,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.104164 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:44.118901 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.119490 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:44.270933 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.151s	user 0.119s	sys 0.031s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":265,"lbm_read_time_us":10655,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29291,"lbm_writes_lt_1ms":543,"mutex_wait_us":57,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2500}
I20260812 06:16:44.271420 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=12.110812
I20260812 06:16:44.320441 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":13743340,"delete_count":0,"lbm_write_time_us":19285,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:16:44.320984 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=1.196750
I20260812 06:16:44.335565 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.014s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3077034,"delete_count":0,"lbm_write_time_us":2789,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:16:44.335999 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:44.348767 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.013s	user 0.004s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4944,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:44.349162 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:44.526150 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.177s	user 0.110s	sys 0.061s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815774,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1125,"lbm_read_time_us":12328,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27858,"lbm_writes_lt_1ms":543,"mutex_wait_us":299,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:16:44.526695 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:44.586650 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.060s	user 0.027s	sys 0.018s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19878,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.587204 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:44.597074 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3755,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.597548 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:44.753849 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.156s	user 0.108s	sys 0.048s 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":587,"lbm_read_time_us":11057,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26006,"lbm_writes_lt_1ms":543,"mutex_wait_us":29,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20736,"update_count":2500}
I20260812 06:16:44.754364 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:44.817807 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.063s	user 0.041s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24210,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:44.818359 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:44.834838 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.016s	user 0.008s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5683,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:44.835314 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:44.994542 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.159s	user 0.108s	sys 0.050s 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":587,"lbm_read_time_us":11348,"lbm_reads_lt_1ms":564,"lbm_write_time_us":26230,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:16:44.995150 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:45.049817 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.054s	user 0.030s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22101,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.050390 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:45.075688 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.025s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4839,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.076165 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:45.085829 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3706,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.086288 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushMRSOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:45.115245 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushMRSOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":247,"dirs.run_wall_time_us":1062,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1346,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:45.115873 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling LogGCOp(c44a61b250404b9b93444cfc235259cd): free 133024360 bytes of WAL
I20260812 06:16:45.116109 22671 log_reader.cc:385] T c44a61b250404b9b93444cfc235259cd: removed 13 log segments from log reader
I20260812 06:16:45.116159 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000003 (ops 12-16)
I20260812 06:16:45.116189 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000004 (ops 17-20)
I20260812 06:16:45.116204 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000005 (ops 21-25)
I20260812 06:16:45.116242 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000006 (ops 26-30)
I20260812 06:16:45.116276 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000007 (ops 31-35)
I20260812 06:16:45.116307 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000008 (ops 36-40)
I20260812 06:16:45.116338 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000009 (ops 41-45)
I20260812 06:16:45.116371 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000010 (ops 46-50)
I20260812 06:16:45.116401 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000011 (ops 51-55)
I20260812 06:16:45.116433 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000012 (ops 56-60)
I20260812 06:16:45.116464 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000013 (ops 61-65)
I20260812 06:16:45.116495 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000014 (ops 66-70)
I20260812 06:16:45.116528 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000015 (ops 71-75)
I20260812 06:16:45.140463 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: LogGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.024s	user 0.000s	sys 0.022s Metrics: {}
I20260812 06:16:45.140906 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=3.181125
I20260812 06:16:45.155244 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.014s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":3967,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:45.155663 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd): 482 bytes on disk
I20260812 06:16:45.156023 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":51,"lbm_reads_lt_1ms":4}
I20260812 06:16:45.156442 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:45.165046 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3220,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:45.165390 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:45.418493 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.253s	user 0.172s	sys 0.080s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123266,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":554,"lbm_read_time_us":18333,"lbm_reads_lt_1ms":875,"lbm_write_time_us":47048,"lbm_writes_lt_1ms":843,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":4736,"thread_start_us":103,"threads_started":1,"update_count":4000}
I20260812 06:16:45.419165 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=19.056125
I20260812 06:16:45.487779 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.068s	user 0.032s	sys 0.025s Metrics: {"bytes_written":20922553,"delete_count":0,"lbm_write_time_us":26676,"lbm_writes_lt_1ms":513,"reinsert_count":0,"update_count":2550}
I20260812 06:16:45.488232 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=6.157687
I20260812 06:16:45.513411 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.025s	user 0.011s	sys 0.008s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":9030,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:16:45.513980 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:45.708711 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.195s	user 0.154s	sys 0.041s Metrics: {"cfile_cache_miss":732,"cfile_cache_miss_bytes":33020506,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":169,"lbm_read_time_us":15112,"lbm_reads_lt_1ms":764,"lbm_write_time_us":41420,"lbm_writes_lt_1ms":743,"mutex_wait_us":40,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":3500}
I20260812 06:16:45.709205 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=18.063937
I20260812 06:16:45.761556 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.052s	user 0.044s	sys 0.004s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":23462,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:45.762072 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:45.777689 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.015s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:45.778131 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:45.941748 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.163s	user 0.102s	sys 0.061s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1006,"lbm_read_time_us":10864,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34127,"lbm_writes_lt_1ms":643,"mutex_wait_us":40,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":3000}
I20260812 06:16:45.942353 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:45.995606 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.053s	user 0.010s	sys 0.041s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23397,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:45.996259 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:46.013892 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.017s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.014358 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:46.167876 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.153s	user 0.103s	sys 0.046s 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":155,"lbm_read_time_us":9230,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27026,"lbm_writes_lt_1ms":543,"mutex_wait_us":38,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2500}
I20260812 06:16:46.168500 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:46.215569 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.047s	user 0.025s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18709,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:16:46.216024 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:46.359844 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.144s	user 0.103s	sys 0.033s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713152,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1277,"lbm_read_time_us":9079,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22389,"lbm_writes_lt_1ms":443,"mutex_wait_us":568,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.360361 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:46.419142 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.059s	user 0.025s	sys 0.033s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27405,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:16:46.419636 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:46.431138 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4412,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.431569 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushMRSOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:46.459616 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushMRSOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.028s	user 0.023s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":1077,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1308,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:16:46.460302 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling LogGCOp(c44a61b250404b9b93444cfc235259cd): free 112239318 bytes of WAL
I20260812 06:16:46.460525 22671 log_reader.cc:385] T c44a61b250404b9b93444cfc235259cd: removed 11 log segments from log reader
I20260812 06:16:46.460580 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000016 (ops 76-80)
I20260812 06:16:46.460620 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000017 (ops 81-85)
I20260812 06:16:46.460654 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000018 (ops 86-90)
I20260812 06:16:46.460685 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000019 (ops 91-94)
I20260812 06:16:46.460716 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000020 (ops 95-99)
I20260812 06:16:46.460748 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000021 (ops 100-104)
I20260812 06:16:46.460778 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000022 (ops 105-109)
I20260812 06:16:46.460809 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000023 (ops 110-114)
I20260812 06:16:46.460839 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000024 (ops 115-119)
I20260812 06:16:46.460866 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000025 (ops 120-124)
I20260812 06:16:46.460896 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000026 (ops 125-129)
I20260812 06:16:46.482882 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: LogGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:16:46.483731 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=3.181125
I20260812 06:16:46.496747 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4348808,"delete_count":0,"lbm_write_time_us":4694,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:16:46.497146 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling LogGCOp(c44a61b250404b9b93444cfc235259cd): free 12017954 bytes of WAL
I20260812 06:16:46.497346 22671 log_reader.cc:385] T c44a61b250404b9b93444cfc235259cd: removed 1 log segments from log reader
I20260812 06:16:46.497406 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000027 (ops 130-134)
I20260812 06:16:46.500128 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: LogGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:16:46.500407 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:46.695387 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.195s	user 0.114s	sys 0.081s Metrics: {"cfile_cache_miss":639,"cfile_cache_miss_bytes":29164363,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":142,"lbm_read_time_us":15247,"lbm_reads_lt_1ms":671,"lbm_write_time_us":32364,"lbm_writes_lt_1ms":649,"peak_mem_usage":75788682,"reinsert_count":0,"spinlock_wait_cycles":23424,"thread_start_us":103,"threads_started":1,"update_count":3030}
I20260812 06:16:46.695938 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd): 462 bytes on disk
I20260812 06:16:46.696589 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: UndoDeltaBlockGCOp(c44a61b250404b9b93444cfc235259cd) 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:16:46.697204 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=18.063937
I20260812 06:16:46.752682 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.055s	user 0.025s	sys 0.028s Metrics: {"bytes_written":20266171,"delete_count":0,"lbm_write_time_us":24814,"lbm_writes_lt_1ms":497,"reinsert_count":0,"update_count":2470}
I20260812 06:16:46.753156 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:46.764480 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.011s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3938,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:46.767598 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:46.968276 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.200s	user 0.120s	sys 0.072s Metrics: {"cfile_cache_miss":626,"cfile_cache_miss_bytes":28671953,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":571,"lbm_read_time_us":14596,"lbm_reads_lt_1ms":658,"lbm_write_time_us":31136,"lbm_writes_lt_1ms":637,"mutex_wait_us":304,"peak_mem_usage":74255878,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2970}
I20260812 06:16:46.968833 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=18.063937
I20260812 06:16:47.035530 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.067s	user 0.036s	sys 0.015s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":24159,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:16:47.036018 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.046613 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3835,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.047281 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:47.234757 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.187s	user 0.140s	sys 0.047s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918096,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":218,"lbm_read_time_us":13836,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31697,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":3000}
I20260812 06:16:47.235350 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=14.095187
I20260812 06:16:47.275956 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.040s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17076,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:16:47.276612 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.296963 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.020s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4852,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.297438 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.307770 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.010s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4083,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.308243 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:47.512804 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.204s	user 0.126s	sys 0.073s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2387,"lbm_read_time_us":14966,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33469,"lbm_writes_lt_1ms":643,"mutex_wait_us":604,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":3000}
I20260812 06:16:47.513407 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=16.079562
I20260812 06:16:47.568356 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.055s	user 0.034s	sys 0.012s Metrics: {"bytes_written":17558579,"delete_count":0,"lbm_write_time_us":21435,"lbm_writes_lt_1ms":431,"reinsert_count":0,"update_count":2140}
I20260812 06:16:47.568888 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.579118 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.010s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3364210,"delete_count":0,"lbm_write_time_us":3202,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:16:47.579563 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.592453 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4896,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.592913 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:47.790742 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.198s	user 0.127s	sys 0.070s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918189,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2214,"lbm_read_time_us":15246,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30329,"lbm_writes_lt_1ms":643,"mutex_wait_us":559,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:16:47.791291 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=15.087375
I20260812 06:16:47.837917 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.046s	user 0.031s	sys 0.011s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":19458,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:16:47.838495 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.860514 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.022s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4441,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.861021 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.872229 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4343,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:16:47.872751 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushMRSOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:47.900924 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushMRSOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":39,"dirs.run_cpu_time_us":226,"dirs.run_wall_time_us":1035,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1462,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:16:47.901602 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling LogGCOp(c44a61b250404b9b93444cfc235259cd): free 121006707 bytes of WAL
I20260812 06:16:47.901813 22671 log_reader.cc:385] T c44a61b250404b9b93444cfc235259cd: removed 12 log segments from log reader
I20260812 06:16:47.901859 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000028 (ops 135-139)
I20260812 06:16:47.901886 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000029 (ops 140-144)
I20260812 06:16:47.901912 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000030 (ops 145-149)
I20260812 06:16:47.901942 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000031 (ops 150-154)
I20260812 06:16:47.901974 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000032 (ops 155-159)
I20260812 06:16:47.902006 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000033 (ops 160-164)
I20260812 06:16:47.902062 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000034 (ops 165-168)
I20260812 06:16:47.902091 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000035 (ops 169-173)
I20260812 06:16:47.902120 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000036 (ops 174-178)
I20260812 06:16:47.902151 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000037 (ops 179-183)
I20260812 06:16:47.902182 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000038 (ops 184-188)
I20260812 06:16:47.902213 22671 log.cc:1079] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: Deleting log segment in path: /tmp/dist-test-taskI1h5Wm/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515398455305-22118-0/minicluster-data/ts-0-root/wals/c44a61b250404b9b93444cfc235259cd/wal-000000039 (ops 189-193)
I20260812 06:16:47.925024 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: LogGCOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {}
I20260812 06:16:47.925359 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=3.181125
I20260812 06:16:47.945305 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.020s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":6404,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:16:47.945749 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd): perf score=2.188937
I20260812 06:16:47.955145 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: FlushDeltaMemStoresOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3613,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:16:47.955694 22788 maintenance_manager.cc:419] P 952fadc8ab9c467295db623f42bf6998: Scheduling MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd): perf score=1.000000
I20260812 06:16:48.037951 22118 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.484s	user 1.613s	sys 0.132s
I20260812 06:16:48.149197 22118 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.111s	user 0.001s	sys 0.000s
I20260812 06:16:48.149672 22118 tablet_server.cc:179] TabletServer@127.21.153.129:0 shutting down...
I20260812 06:16:48.185861 22671 maintenance_manager.cc:643] P 952fadc8ab9c467295db623f42bf6998: MajorDeltaCompactionOp(c44a61b250404b9b93444cfc235259cd) complete. Timing: real 0.230s	user 0.154s	sys 0.076s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37123253,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1210,"lbm_read_time_us":18168,"lbm_reads_lt_1ms":871,"lbm_write_time_us":39643,"lbm_writes_lt_1ms":843,"mutex_wait_us":599,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":8064,"thread_start_us":70,"threads_started":1,"update_count":4000}
I20260812 06:16:48.186357 22118 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:16:48.186699 22118 tablet_replica.cc:333] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998: stopping tablet replica
I20260812 06:16:48.186831 22118 raft_consensus.cc:2243] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.187037 22118 raft_consensus.cc:2272] T c44a61b250404b9b93444cfc235259cd P 952fadc8ab9c467295db623f42bf6998 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.192154 22118 tablet_server.cc:196] TabletServer@127.21.153.129:0 shutdown complete.
I20260812 06:16:48.256491 22118 master.cc:562] Master@127.21.153.190:39683 shutting down...
I20260812 06:16:48.259268 22118 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:16:48.259454 22118 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:16:48.259529 22118 tablet_replica.cc:333] T 00000000000000000000000000000000 P 1bd79e20abce4edda749275208082c71: stopping tablet replica
I20260812 06:16:48.271929 22118 master.cc:584] Master@127.21.153.190:39683 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4938 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9879 ms total)

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