[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:22.588506  3097 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.6.126:34201
I20260812 06:19:22.589452  3097 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:22.590021  3097 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:22.595873  3106 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:22.596060  3103 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:19:22.596083  3097 server_base.cc:1061] running on GCE node
W20260812 06:19:22.596478  3102 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:22.596926  3097 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:22.597008  3097 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:22.597038  3097 hybrid_clock.cc:648] HybridClock initialized: now 1786515562597037 us; error 0 us; skew 500 ppm
I20260812 06:19:22.598646  3097 webserver.cc:533] Webserver started at http://127.3.6.126:39753/ using document root <none> and password file <none>
I20260812 06:19:22.599146  3097 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:22.599208  3097 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:22.599382  3097 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:22.600917  3097 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/master-0-root/instance:
uuid: "06b7862d91d94aa4af489687e72eb2c0"
format_stamp: "Formatted at 2026-08-12 06:19:22 on dist-test-slave-zkpd"
I20260812 06:19:22.604265  3097 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:22.606187  3111 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:22.607138  3097 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:22.607230  3097 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/master-0-root
uuid: "06b7862d91d94aa4af489687e72eb2c0"
format_stamp: "Formatted at 2026-08-12 06:19:22 on dist-test-slave-zkpd"
I20260812 06:19:22.607304  3097 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:22.623239  3097 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:22.623814  3097 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:22.624033  3097 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:22.631583  3097 rpc_server.cc:307] RPC server started. Bound to: 127.3.6.126:34201
I20260812 06:19:22.631594  3167 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.6.126:34201 every 8 connection(s)
I20260812 06:19:22.633872  3168 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:22.639197  3168 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: Bootstrap starting.
I20260812 06:19:22.641525  3168 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:22.642418  3168 log.cc:826] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:22.644075  3168 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: No bootstrap required, opened a new log
I20260812 06:19:22.646729  3168 raft_consensus.cc:359] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER }
I20260812 06:19:22.646931  3168 raft_consensus.cc:385] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:22.647050  3168 raft_consensus.cc:740] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 06b7862d91d94aa4af489687e72eb2c0, State: Initialized, Role: FOLLOWER
I20260812 06:19:22.647644  3168 consensus_queue.cc:260] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [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: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER }
I20260812 06:19:22.647845  3168 raft_consensus.cc:399] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:22.647950  3168 raft_consensus.cc:493] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:22.648099  3168 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:22.651422  3168 raft_consensus.cc:515] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER }
I20260812 06:19:22.651952  3168 leader_election.cc:304] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [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: 06b7862d91d94aa4af489687e72eb2c0; no voters: 
I20260812 06:19:22.652300  3168 leader_election.cc:290] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:22.652442  3172 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:22.652683  3172 raft_consensus.cc:697] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 1 LEADER]: Becoming Leader. State: Replica: 06b7862d91d94aa4af489687e72eb2c0, State: Running, Role: LEADER
I20260812 06:19:22.653128  3172 consensus_queue.cc:237] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [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: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER }
I20260812 06:19:22.653451  3168 sys_catalog.cc:565] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:22.655156  3173 sys_catalog.cc:455] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "06b7862d91d94aa4af489687e72eb2c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER } }
I20260812 06:19:22.655189  3174 sys_catalog.cc:455] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 06b7862d91d94aa4af489687e72eb2c0. Latest consensus state: current_term: 1 leader_uuid: "06b7862d91d94aa4af489687e72eb2c0" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "06b7862d91d94aa4af489687e72eb2c0" member_type: VOTER } }
I20260812 06:19:22.655294  3173 sys_catalog.cc:458] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:22.655294  3174 sys_catalog.cc:458] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:22.655768  3182 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:22.656172  3097 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:22.657913  3182 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:22.662411  3182 catalog_manager.cc:1383] Generated new cluster ID: 0a05445b184342aebe57c3c02b5e60b9
I20260812 06:19:22.662470  3182 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:22.673806  3182 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:22.674553  3182 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:22.681726  3182 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: Generated new TSK 0
I20260812 06:19:22.682250  3182 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:22.688690  3097 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:22.691109  3192 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:22.691215  3194 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:22.691511  3191 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:22.691519  3097 server_base.cc:1061] running on GCE node
I20260812 06:19:22.691756  3097 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:22.691798  3097 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:22.691813  3097 hybrid_clock.cc:648] HybridClock initialized: now 1786515562691814 us; error 0 us; skew 500 ppm
I20260812 06:19:22.692787  3097 webserver.cc:533] Webserver started at http://127.3.6.65:45773/ using document root <none> and password file <none>
I20260812 06:19:22.692961  3097 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:22.693015  3097 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:22.693107  3097 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:22.693486  3097 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/instance:
uuid: "44cd6f1f770b4e1bbc166e1256651778"
format_stamp: "Formatted at 2026-08-12 06:19:22 on dist-test-slave-zkpd"
I20260812 06:19:22.695000  3097 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:22.696034  3199 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:22.696342  3097 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:22.696415  3097 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root
uuid: "44cd6f1f770b4e1bbc166e1256651778"
format_stamp: "Formatted at 2026-08-12 06:19:22 on dist-test-slave-zkpd"
I20260812 06:19:22.696499  3097 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:22.723771  3097 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:22.724277  3097 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:22.724960  3097 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:22.725925  3097 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:22.725986  3097 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:22.726056  3097 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:22.726101  3097 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:22.733378  3097 rpc_server.cc:307] RPC server started. Bound to: 127.3.6.65:44787
I20260812 06:19:22.733450  3266 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.6.65:44787 every 8 connection(s)
I20260812 06:19:22.747843  3267 heartbeater.cc:344] Connected to a master server at 127.3.6.126:34201
I20260812 06:19:22.748116  3267 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:22.748534  3267 heartbeater.cc:507] Master 127.3.6.126:34201 requested a full tablet report, sending...
I20260812 06:19:22.749908  3129 ts_manager.cc:194] Registered new tserver with Master: 44cd6f1f770b4e1bbc166e1256651778 (127.3.6.65:44787)
I20260812 06:19:22.750845  3097 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.016747812s
I20260812 06:19:22.751048  3129 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:48840
I20260812 06:19:22.760092  3129 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:48852:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:22.772667  3229 tablet_service.cc:1511] Processing CreateTablet for tablet 21d8dd985a5a4037aed14e94535e5efe (DEFAULT_TABLE table=heavy-update-compaction-test [id=4a6313a7f6b1468db2c54e2b6820bdd6]), partition=
I20260812 06:19:22.773079  3229 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 21d8dd985a5a4037aed14e94535e5efe. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:22.775410  3279 tablet_bootstrap.cc:492] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Bootstrap starting.
I20260812 06:19:22.776593  3279 tablet_bootstrap.cc:654] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:22.777851  3279 tablet_bootstrap.cc:492] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: No bootstrap required, opened a new log
I20260812 06:19:22.777974  3279 ts_tablet_manager.cc:1403] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Time spent bootstrapping tablet: real 0.003s	user 0.000s	sys 0.002s
I20260812 06:19:22.778471  3279 raft_consensus.cc:359] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44cd6f1f770b4e1bbc166e1256651778" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 44787 } }
I20260812 06:19:22.778589  3279 raft_consensus.cc:385] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:22.778630  3279 raft_consensus.cc:740] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 44cd6f1f770b4e1bbc166e1256651778, State: Initialized, Role: FOLLOWER
I20260812 06:19:22.778769  3279 consensus_queue.cc:260] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [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: "44cd6f1f770b4e1bbc166e1256651778" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 44787 } }
I20260812 06:19:22.778860  3279 raft_consensus.cc:399] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:22.778894  3279 raft_consensus.cc:493] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:22.778946  3279 raft_consensus.cc:3060] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:22.779932  3279 raft_consensus.cc:515] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44cd6f1f770b4e1bbc166e1256651778" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 44787 } }
I20260812 06:19:22.780087  3279 leader_election.cc:304] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [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: 44cd6f1f770b4e1bbc166e1256651778; no voters: 
I20260812 06:19:22.780279  3279 leader_election.cc:290] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:22.780406  3281 raft_consensus.cc:2804] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:22.780666  3279 ts_tablet_manager.cc:1434] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Time spent starting tablet: real 0.003s	user 0.002s	sys 0.001s
I20260812 06:19:22.780961  3267 heartbeater.cc:499] Master 127.3.6.126:34201 was elected leader, sending a full tablet report...
I20260812 06:19:22.781440  3281 raft_consensus.cc:697] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 1 LEADER]: Becoming Leader. State: Replica: 44cd6f1f770b4e1bbc166e1256651778, State: Running, Role: LEADER
I20260812 06:19:22.781565  3281 consensus_queue.cc:237] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [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: "44cd6f1f770b4e1bbc166e1256651778" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 44787 } }
I20260812 06:19:22.784271  3129 catalog_manager.cc:5719] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 reported cstate change: term changed from 0 to 1, leader changed from <none> to 44cd6f1f770b4e1bbc166e1256651778 (127.3.6.65). New cstate: current_term: 1 leader_uuid: "44cd6f1f770b4e1bbc166e1256651778" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "44cd6f1f770b4e1bbc166e1256651778" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 44787 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:22.851070  3097 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.057s	user 0.015s	sys 0.011s
I20260812 06:19:22.985687  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe): perf score=18.062753
I20260812 06:19:23.180042  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.194s	user 0.125s	sys 0.058s Metrics: {"bytes_written":12307491,"cfile_init":1,"compiler_manager_pool.queue_time_us":173,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":979,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46966,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":97,"threads_started":1,"update_count":1500}
I20260812 06:19:23.181274  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling LogGCOp(21d8dd985a5a4037aed14e94535e5efe): free 20743880 bytes of WAL
I20260812 06:19:23.181559  3204 log_reader.cc:385] T 21d8dd985a5a4037aed14e94535e5efe: removed 2 log segments from log reader
I20260812 06:19:23.181617  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000001 (ops 1-6)
I20260812 06:19:23.181666  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000002 (ops 7-11)
I20260812 06:19:23.187505  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: LogGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.006s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:23.187835  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.203015  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.015s	user 0.007s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5743,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.203483  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:23.347575  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.144s	user 0.100s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":480,"lbm_read_time_us":8161,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24158,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"thread_start_us":391,"threads_started":5,"update_count":2000}
I20260812 06:19:23.348531  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=10.126437
I20260812 06:19:23.395251  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.046s	user 0.020s	sys 0.023s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":20156,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:23.395699  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe): 16411395 bytes on disk
I20260812 06:19:23.396179  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4}
I20260812 06:19:23.396544  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.413371  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6051,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.413882  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:23.533987  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.120s	user 0.093s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1077,"lbm_read_time_us":7381,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24688,"lbm_writes_lt_1ms":443,"mutex_wait_us":297,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2048,"update_count":2000}
I20260812 06:19:23.534562  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=11.118625
I20260812 06:19:23.572865  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.038s	user 0.026s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14252,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:23.573458  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.593632  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.020s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4005,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.594070  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.604357  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4052,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:23.604743  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:23.771523  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.167s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":248,"lbm_read_time_us":10592,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32476,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:23.772171  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=12.110812
I20260812 06:19:23.821071  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.049s	user 0.026s	sys 0.020s Metrics: {"bytes_written":13538209,"delete_count":0,"lbm_write_time_us":19370,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":332,"reinsert_count":0,"update_count":1650}
I20260812 06:19:23.821504  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.836879  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.015s	user 0.008s	sys 0.000s Metrics: {"bytes_written":3282159,"delete_count":0,"lbm_write_time_us":3457,"lbm_writes_lt_1ms":83,"reinsert_count":0,"update_count":400}
I20260812 06:19:23.837283  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:23.846499  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3811,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:23.846851  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:24.018404  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.171s	user 0.096s	sys 0.064s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774773,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":138,"lbm_read_time_us":13113,"lbm_reads_lt_1ms":573,"lbm_write_time_us":26496,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:24.019063  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:24.076068  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.057s	user 0.037s	sys 0.015s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22668,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.076570  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.088680  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4978,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.089120  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:24.245302  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.156s	user 0.102s	sys 0.051s 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":152,"lbm_read_time_us":12123,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26378,"lbm_writes_lt_1ms":543,"mutex_wait_us":37,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:24.245884  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:24.304697  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.059s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21408,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.305388  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.323628  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.018s	user 0.012s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7235,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.324188  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:24.358794  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.034s	user 0.028s	sys 0.002s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":103,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":1294,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2187,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:24.359764  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling LogGCOp(21d8dd985a5a4037aed14e94535e5efe): free 112239267 bytes of WAL
I20260812 06:19:24.360035  3204 log_reader.cc:385] T 21d8dd985a5a4037aed14e94535e5efe: removed 11 log segments from log reader
I20260812 06:19:24.360106  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000003 (ops 12-16)
I20260812 06:19:24.360163  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000004 (ops 17-20)
I20260812 06:19:24.360221  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000005 (ops 21-25)
I20260812 06:19:24.360291  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000006 (ops 26-30)
I20260812 06:19:24.360351  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000007 (ops 31-35)
I20260812 06:19:24.360394  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000008 (ops 36-40)
I20260812 06:19:24.360433  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000009 (ops 41-45)
I20260812 06:19:24.360472  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000010 (ops 46-50)
I20260812 06:19:24.360512  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000011 (ops 51-55)
I20260812 06:19:24.360551  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000012 (ops 56-60)
I20260812 06:19:24.360590  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000013 (ops 61-65)
I20260812 06:19:24.385713  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: LogGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:24.386133  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.400650  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4581,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.401048  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.411794  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4516,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.412266  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe): 447 bytes on disk
I20260812 06:19:24.412648  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:24.413064  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:24.628297  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.215s	user 0.159s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":408,"lbm_read_time_us":15478,"lbm_reads_lt_1ms":774,"lbm_write_time_us":41620,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:24.628931  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=15.087375
I20260812 06:19:24.675472  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.046s	user 0.019s	sys 0.024s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":19921,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:24.676205  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.692512  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.016s	user 0.010s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5856,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:24.692978  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:24.852516  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.159s	user 0.133s	sys 0.016s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774676,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":192,"lbm_read_time_us":9882,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30197,"lbm_writes_lt_1ms":543,"mutex_wait_us":44,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:24.853164  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:24.916450  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.063s	user 0.034s	sys 0.022s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26521,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:24.916931  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:24.927328  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3912,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:24.927999  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:25.109035  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.181s	user 0.143s	sys 0.028s 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":1170,"lbm_read_time_us":12166,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31176,"lbm_writes_lt_1ms":543,"mutex_wait_us":313,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2500}
I20260812 06:19:25.109524  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:25.180136  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.070s	user 0.040s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":30288,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.180619  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:25.190678  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.191085  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:25.356806  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.166s	user 0.113s	sys 0.048s 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":147,"lbm_read_time_us":11895,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29402,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6528,"update_count":2500}
I20260812 06:19:25.357465  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:25.412256  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":22117,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.412788  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:25.429112  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.429842  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:25.610365  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.180s	user 0.120s	sys 0.052s 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":337,"lbm_read_time_us":12676,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29961,"lbm_writes_lt_1ms":543,"mutex_wait_us":25,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:25.610838  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:25.672438  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.061s	user 0.007s	sys 0.047s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20816,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.672932  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:25.683990  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4306,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.684365  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:25.861896  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.177s	user 0.115s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":209,"lbm_read_time_us":11809,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28673,"lbm_writes_lt_1ms":543,"mutex_wait_us":67,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13696,"update_count":2500}
I20260812 06:19:25.862569  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:25.913270  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.051s	user 0.038s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20697,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:25.913776  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:25.932096  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.018s	user 0.007s	sys 0.011s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3948,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:25.932549  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:25.966686  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.034s	user 0.030s	sys 0.001s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":71,"dirs.run_cpu_time_us":245,"dirs.run_wall_time_us":1326,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1525,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:25.967456  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling LogGCOp(21d8dd985a5a4037aed14e94535e5efe): free 132571365 bytes of WAL
I20260812 06:19:25.967684  3204 log_reader.cc:385] T 21d8dd985a5a4037aed14e94535e5efe: removed 13 log segments from log reader
I20260812 06:19:25.967728  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000014 (ops 66-70)
I20260812 06:19:25.967757  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000015 (ops 71-75)
I20260812 06:19:25.967816  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000016 (ops 76-80)
I20260812 06:19:25.967859  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000017 (ops 81-84)
I20260812 06:19:25.967970  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000018 (ops 85-89)
I20260812 06:19:25.968014  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000019 (ops 90-94)
I20260812 06:19:25.968045  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000020 (ops 95-98)
I20260812 06:19:25.968084  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000021 (ops 99-103)
I20260812 06:19:25.968120  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000022 (ops 104-108)
I20260812 06:19:25.968158  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000023 (ops 109-113)
I20260812 06:19:25.968194  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000024 (ops 114-118)
I20260812 06:19:25.968231  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000025 (ops 119-123)
I20260812 06:19:25.968267  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000026 (ops 124-128)
I20260812 06:19:25.996459  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: LogGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.029s	user 0.006s	sys 0.023s Metrics: {}
I20260812 06:19:25.996984  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe): 493 bytes on disk
I20260812 06:19:25.997408  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe) 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:19:25.998047  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=3.181125
I20260812 06:19:26.020932  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.023s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7444,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:26.021432  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:26.034855  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5302,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.035312  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:26.261117  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.226s	user 0.152s	sys 0.064s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":143,"lbm_read_time_us":14287,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37122,"lbm_writes_lt_1ms":743,"mutex_wait_us":30,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":4224,"thread_start_us":77,"threads_started":1,"update_count":3500}
I20260812 06:19:26.261762  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=18.063937
I20260812 06:19:26.328886  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.067s	user 0.040s	sys 0.016s Metrics: {"bytes_written":20512319,"delete_count":0,"lbm_write_time_us":25944,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:26.329342  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:26.341490  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4360,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:26.342119  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:26.541971  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.200s	user 0.140s	sys 0.059s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877106,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":228,"lbm_read_time_us":13913,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34797,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:19:26.542769  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:26.606423  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.063s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26877,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:26.606915  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=3.181125
I20260812 06:19:26.625021  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.018s	user 0.016s	sys 0.001s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":7321,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:26.625571  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:26.635270  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3771,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:26.635865  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:26.843225  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.207s	user 0.146s	sys 0.061s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":759,"lbm_read_time_us":14767,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36644,"lbm_writes_lt_1ms":643,"mutex_wait_us":316,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":3000}
I20260812 06:19:26.844040  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:26.899179  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.055s	user 0.038s	sys 0.013s Metrics: {"bytes_written":16532973,"delete_count":0,"lbm_write_time_us":24378,"lbm_writes_lt_1ms":406,"mutex_wait_us":693,"reinsert_count":0,"update_count":2015}
I20260812 06:19:26.899685  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:26.914399  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:19:26.914896  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:27.082254  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.167s	user 0.122s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774685,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":776,"lbm_read_time_us":12322,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28496,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:19:27.082968  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:27.139880  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.057s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19659,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.140370  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:27.151816  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4358,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.152437  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:27.320966  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.168s	user 0.116s	sys 0.052s 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":708,"lbm_read_time_us":12341,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28334,"lbm_writes_lt_1ms":543,"mutex_wait_us":19,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:19:27.321602  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=14.095187
I20260812 06:19:27.379475  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.058s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21241,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:27.380120  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:27.390691  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.391110  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:27.431376  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushMRSOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.040s	user 0.026s	sys 0.003s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":266,"dirs.run_wall_time_us":1413,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1771,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:27.432408  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling LogGCOp(21d8dd985a5a4037aed14e94535e5efe): free 121006648 bytes of WAL
I20260812 06:19:27.432679  3204 log_reader.cc:385] T 21d8dd985a5a4037aed14e94535e5efe: removed 12 log segments from log reader
I20260812 06:19:27.432751  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000027 (ops 129-133)
I20260812 06:19:27.432799  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000028 (ops 134-138)
I20260812 06:19:27.432857  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000029 (ops 139-143)
I20260812 06:19:27.432900  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000030 (ops 144-148)
I20260812 06:19:27.432937  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000031 (ops 149-152)
I20260812 06:19:27.432977  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000032 (ops 153-157)
I20260812 06:19:27.433018  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000033 (ops 158-162)
I20260812 06:19:27.433058  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000034 (ops 163-167)
I20260812 06:19:27.433099  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000035 (ops 168-172)
I20260812 06:19:27.433138  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000036 (ops 173-177)
I20260812 06:19:27.433177  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000037 (ops 178-182)
I20260812 06:19:27.433218  3204 log.cc:1079] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/21d8dd985a5a4037aed14e94535e5efe/wal-000000038 (ops 183-187)
I20260812 06:19:27.459596  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: LogGCOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:27.460181  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:27.478048  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.018s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5193,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.478566  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe): 462 bytes on disk
I20260812 06:19:27.478987  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: UndoDeltaBlockGCOp(21d8dd985a5a4037aed14e94535e5efe) 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:19:27.479606  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=2.188937
I20260812 06:19:27.490008  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:27.490610  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe): perf score=1.000000
I20260812 06:19:27.724710  3097 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.873s	user 1.775s	sys 0.148s
I20260812 06:19:27.727002  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: MajorDeltaCompactionOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.236s	user 0.128s	sys 0.103s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979752,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":918,"lbm_read_time_us":16558,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39788,"lbm_writes_lt_1ms":743,"mutex_wait_us":268,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":768,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:19:27.728024  3268 maintenance_manager.cc:419] P 44cd6f1f770b4e1bbc166e1256651778: Scheduling FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe): perf score=18.063937
I20260812 06:19:27.758083  3097 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.033s	user 0.002s	sys 0.000s
I20260812 06:19:27.758810  3097 tablet_server.cc:179] TabletServer@127.3.6.65:0 shutting down...
I20260812 06:19:27.791610  3204 maintenance_manager.cc:643] P 44cd6f1f770b4e1bbc166e1256651778: FlushDeltaMemStoresOp(21d8dd985a5a4037aed14e94535e5efe) complete. Timing: real 0.063s	user 0.026s	sys 0.033s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":28913,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:27.792272  3097 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:27.792658  3097 tablet_replica.cc:333] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778: stopping tablet replica
I20260812 06:19:27.792889  3097 raft_consensus.cc:2243] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.793113  3097 raft_consensus.cc:2272] T 21d8dd985a5a4037aed14e94535e5efe P 44cd6f1f770b4e1bbc166e1256651778 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.807356  3097 tablet_server.cc:196] TabletServer@127.3.6.65:0 shutdown complete.
I20260812 06:19:27.811755  3097 master.cc:562] Master@127.3.6.126:34201 shutting down...
I20260812 06:19:27.815229  3097 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:27.815398  3097 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:27.815491  3097 tablet_replica.cc:333] T 00000000000000000000000000000000 P 06b7862d91d94aa4af489687e72eb2c0: stopping tablet replica
I20260812 06:19:27.827436  3097 master.cc:584] Master@127.3.6.126:34201 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5327 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:27.915717  3097 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.6.126:36741
I20260812 06:19:27.916126  3097 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:27.918226  3303 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:27.918360  3305 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:27.918445  3097 server_base.cc:1061] running on GCE node
W20260812 06:19:27.918582  3302 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:27.918799  3097 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:27.918843  3097 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:27.918860  3097 hybrid_clock.cc:648] HybridClock initialized: now 1786515567918860 us; error 0 us; skew 500 ppm
I20260812 06:19:27.919687  3097 webserver.cc:533] Webserver started at http://127.3.6.126:32807/ using document root <none> and password file <none>
I20260812 06:19:27.919871  3097 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:27.919966  3097 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:27.920058  3097 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:27.920445  3097 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/master-0-root/instance:
uuid: "20df7d8ccfe34643bd479546366dbc27"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-zkpd"
I20260812 06:19:27.921948  3097 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:27.922842  3310 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:27.923070  3097 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:27.923161  3097 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/master-0-root
uuid: "20df7d8ccfe34643bd479546366dbc27"
format_stamp: "Formatted at 2026-08-12 06:19:27 on dist-test-slave-zkpd"
I20260812 06:19:27.923244  3097 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:27.930054  3097 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:27.930359  3097 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:27.934440  3097 rpc_server.cc:307] RPC server started. Bound to: 127.3.6.126:36741
I20260812 06:19:27.940127  3367 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.6.126:36741 every 8 connection(s)
I20260812 06:19:27.940788  3368 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:27.944139  3368 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27: Bootstrap starting.
I20260812 06:19:27.949142  3368 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:27.955796  3368 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27: No bootstrap required, opened a new log
I20260812 06:19:27.956184  3368 raft_consensus.cc:359] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER }
I20260812 06:19:27.956269  3368 raft_consensus.cc:385] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:27.956295  3368 raft_consensus.cc:740] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 20df7d8ccfe34643bd479546366dbc27, State: Initialized, Role: FOLLOWER
I20260812 06:19:27.956403  3368 consensus_queue.cc:260] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [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: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER }
I20260812 06:19:27.956465  3368 raft_consensus.cc:399] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:27.956486  3368 raft_consensus.cc:493] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:27.956516  3368 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:27.957160  3368 raft_consensus.cc:515] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER }
I20260812 06:19:27.957276  3368 leader_election.cc:304] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [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: 20df7d8ccfe34643bd479546366dbc27; no voters: 
I20260812 06:19:27.957419  3368 leader_election.cc:290] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:27.957604  3371 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:27.957868  3371 raft_consensus.cc:697] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 1 LEADER]: Becoming Leader. State: Replica: 20df7d8ccfe34643bd479546366dbc27, State: Running, Role: LEADER
I20260812 06:19:27.957875  3368 sys_catalog.cc:565] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:27.958024  3371 consensus_queue.cc:237] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [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: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER }
I20260812 06:19:27.958491  3372 sys_catalog.cc:455] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "20df7d8ccfe34643bd479546366dbc27" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER } }
I20260812 06:19:27.958524  3373 sys_catalog.cc:455] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 20df7d8ccfe34643bd479546366dbc27. Latest consensus state: current_term: 1 leader_uuid: "20df7d8ccfe34643bd479546366dbc27" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "20df7d8ccfe34643bd479546366dbc27" member_type: VOTER } }
I20260812 06:19:27.958675  3373 sys_catalog.cc:458] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:27.958658  3372 sys_catalog.cc:458] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:27.959242  3379 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:27.960222  3379 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:27.960428  3097 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:27.962049  3379 catalog_manager.cc:1383] Generated new cluster ID: d312bb769b404136a418aa3688aa5103
I20260812 06:19:27.962103  3379 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:27.990530  3379 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:27.991088  3379 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:27.995494  3379 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27: Generated new TSK 0
I20260812 06:19:27.995643  3379 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:28.024927  3097 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:28.026854  3389 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:19:28.026907  3390 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:28.026969  3392 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:28.026985  3097 server_base.cc:1061] running on GCE node
I20260812 06:19:28.027305  3097 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:28.027347  3097 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:28.027364  3097 hybrid_clock.cc:648] HybridClock initialized: now 1786515568027363 us; error 0 us; skew 500 ppm
I20260812 06:19:28.028283  3097 webserver.cc:533] Webserver started at http://127.3.6.65:39713/ using document root <none> and password file <none>
I20260812 06:19:28.028461  3097 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:28.028508  3097 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:28.028605  3097 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:28.029018  3097 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/instance:
uuid: "f6b255a346e64e41bdc00183efd13bd7"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-zkpd"
I20260812 06:19:28.030541  3097 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:28.031425  3397 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:28.031670  3097 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:28.031766  3097 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root
uuid: "f6b255a346e64e41bdc00183efd13bd7"
format_stamp: "Formatted at 2026-08-12 06:19:28 on dist-test-slave-zkpd"
I20260812 06:19:28.031853  3097 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:28.048409  3097 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:28.048764  3097 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:28.049065  3097 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:28.049532  3097 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:28.049592  3097 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:28.049649  3097 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:28.049700  3097 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:28.053867  3097 rpc_server.cc:307] RPC server started. Bound to: 127.3.6.65:41579
I20260812 06:19:28.053902  3465 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.6.65:41579 every 8 connection(s)
I20260812 06:19:28.061131  3466 heartbeater.cc:344] Connected to a master server at 127.3.6.126:36741
I20260812 06:19:28.061266  3466 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:28.061479  3466 heartbeater.cc:507] Master 127.3.6.126:36741 requested a full tablet report, sending...
I20260812 06:19:28.062165  3329 ts_manager.cc:194] Registered new tserver with Master: f6b255a346e64e41bdc00183efd13bd7 (127.3.6.65:41579)
I20260812 06:19:28.062884  3329 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38522
I20260812 06:19:28.063050  3097 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.008755535s
I20260812 06:19:28.069737  3329 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38530:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:28.078147  3426 tablet_service.cc:1511] Processing CreateTablet for tablet a195840ef6b74fb68318150997ad5629 (DEFAULT_TABLE table=heavy-update-compaction-test [id=7385dd532620486687ec214b43ba1cd0]), partition=
I20260812 06:19:28.078418  3426 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet a195840ef6b74fb68318150997ad5629. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:28.080320  3478 tablet_bootstrap.cc:492] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Bootstrap starting.
I20260812 06:19:28.081246  3478 tablet_bootstrap.cc:654] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:28.082249  3478 tablet_bootstrap.cc:492] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: No bootstrap required, opened a new log
I20260812 06:19:28.082355  3478 ts_tablet_manager.cc:1403] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:28.082755  3478 raft_consensus.cc:359] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f6b255a346e64e41bdc00183efd13bd7" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 41579 } }
I20260812 06:19:28.082866  3478 raft_consensus.cc:385] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:28.082912  3478 raft_consensus.cc:740] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: f6b255a346e64e41bdc00183efd13bd7, State: Initialized, Role: FOLLOWER
I20260812 06:19:28.083065  3478 consensus_queue.cc:260] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [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: "f6b255a346e64e41bdc00183efd13bd7" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 41579 } }
I20260812 06:19:28.083155  3478 raft_consensus.cc:399] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:28.083200  3478 raft_consensus.cc:493] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:28.083250  3478 raft_consensus.cc:3060] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:28.084280  3478 raft_consensus.cc:515] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f6b255a346e64e41bdc00183efd13bd7" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 41579 } }
I20260812 06:19:28.084424  3478 leader_election.cc:304] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [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: f6b255a346e64e41bdc00183efd13bd7; no voters: 
I20260812 06:19:28.084626  3478 leader_election.cc:290] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:28.084712  3480 raft_consensus.cc:2804] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:28.084954  3480 raft_consensus.cc:697] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 1 LEADER]: Becoming Leader. State: Replica: f6b255a346e64e41bdc00183efd13bd7, State: Running, Role: LEADER
I20260812 06:19:28.085008  3466 heartbeater.cc:499] Master 127.3.6.126:36741 was elected leader, sending a full tablet report...
I20260812 06:19:28.084986  3478 ts_tablet_manager.cc:1434] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:28.085137  3480 consensus_queue.cc:237] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [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: "f6b255a346e64e41bdc00183efd13bd7" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 41579 } }
I20260812 06:19:28.086427  3329 catalog_manager.cc:5719] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 reported cstate change: term changed from 0 to 1, leader changed from <none> to f6b255a346e64e41bdc00183efd13bd7 (127.3.6.65). New cstate: current_term: 1 leader_uuid: "f6b255a346e64e41bdc00183efd13bd7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "f6b255a346e64e41bdc00183efd13bd7" member_type: VOTER last_known_addr { host: "127.3.6.65" port: 41579 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:28.148519  3097 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.016s	sys 0.008s
I20260812 06:19:28.304703  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushMRSOp(a195840ef6b74fb68318150997ad5629): perf score=19.054940
I20260812 06:19:28.470994  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushMRSOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.166s	user 0.130s	sys 0.032s Metrics: {"bytes_written":12512611,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":75,"dirs.run_cpu_time_us":199,"dirs.run_wall_time_us":822,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43565,"lbm_writes_lt_1ms":762,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1525}
I20260812 06:19:28.471678  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling LogGCOp(a195840ef6b74fb68318150997ad5629): free 20290830 bytes of WAL
I20260812 06:19:28.471982  3402 log_reader.cc:385] T a195840ef6b74fb68318150997ad5629: removed 2 log segments from log reader
I20260812 06:19:28.472093  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000001 (ops 1-6)
I20260812 06:19:28.472165  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000002 (ops 7-10)
I20260812 06:19:28.478386  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: LogGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:28.478726  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=3.181125
I20260812 06:19:28.502614  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.024s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4307786,"delete_count":0,"lbm_write_time_us":4819,"lbm_writes_lt_1ms":108,"reinsert_count":0,"update_count":525}
I20260812 06:19:28.503152  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629): 16411396 bytes on disk
I20260812 06:19:28.503577  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629) 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:19:28.504071  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:28.513722  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3853,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:28.514248  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:28.684618  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.170s	user 0.122s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774802,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":499,"lbm_read_time_us":12239,"lbm_reads_lt_1ms":569,"lbm_write_time_us":30759,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":325,"threads_started":5,"update_count":2500}
I20260812 06:19:28.685283  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:28.734951  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.049s	user 0.034s	sys 0.004s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17660,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.735459  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:28.751037  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.015s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5897,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:28.751670  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:28.922637  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.171s	user 0.112s	sys 0.049s 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":605,"lbm_read_time_us":11527,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30325,"lbm_writes_lt_1ms":543,"mutex_wait_us":75,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:19:28.923336  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:28.995810  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.072s	user 0.022s	sys 0.036s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26767,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:28.996300  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:29.008911  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4728,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.009366  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:29.192983  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.183s	user 0.116s	sys 0.067s 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":328,"lbm_read_time_us":13109,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32160,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:29.193555  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:29.243430  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.050s	user 0.037s	sys 0.010s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21778,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.243992  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:29.255380  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.255883  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:29.426955  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.171s	user 0.115s	sys 0.053s 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":846,"lbm_read_time_us":11885,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28048,"lbm_writes_lt_1ms":543,"mutex_wait_us":331,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:29.427613  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:29.496861  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.069s	user 0.025s	sys 0.043s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":26657,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.497355  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:29.508059  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4221,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.508548  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:29.694741  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.186s	user 0.122s	sys 0.052s 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":181,"lbm_read_time_us":12904,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28008,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:19:29.695255  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:29.751255  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.056s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22579,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:29.751740  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:29.773016  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.021s	user 0.009s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4392,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:29.773509  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushMRSOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:29.804386  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushMRSOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.031s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1391,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1591,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:29.804963  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling LogGCOp(a195840ef6b74fb68318150997ad5629): free 121006431 bytes of WAL
I20260812 06:19:29.805169  3402 log_reader.cc:385] T a195840ef6b74fb68318150997ad5629: removed 12 log segments from log reader
I20260812 06:19:29.805230  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000003 (ops 11-15)
I20260812 06:19:29.805290  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000004 (ops 16-20)
I20260812 06:19:29.805343  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000005 (ops 21-24)
I20260812 06:19:29.805387  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000006 (ops 25-29)
I20260812 06:19:29.805428  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000007 (ops 30-34)
I20260812 06:19:29.805472  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000008 (ops 35-39)
I20260812 06:19:29.805509  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000009 (ops 40-44)
I20260812 06:19:29.805545  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000010 (ops 45-49)
I20260812 06:19:29.805580  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000011 (ops 50-54)
I20260812 06:19:29.805617  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000012 (ops 55-59)
I20260812 06:19:29.805653  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000013 (ops 60-64)
I20260812 06:19:29.805691  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000014 (ops 65-69)
I20260812 06:19:29.831329  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: LogGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:29.831732  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=3.181125
I20260812 06:19:29.853003  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.021s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7137,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:29.853394  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:29.863087  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:29.863512  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629): 471 bytes on disk
I20260812 06:19:29.863943  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:19:29.864367  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:30.113351  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.249s	user 0.113s	sys 0.121s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979738,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":3991,"lbm_read_time_us":15428,"lbm_reads_lt_1ms":774,"lbm_write_time_us":38736,"lbm_writes_lt_1ms":743,"mutex_wait_us":1913,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":2176,"thread_start_us":104,"threads_started":1,"update_count":3500}
I20260812 06:19:30.114002  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=18.063937
I20260812 06:19:30.183743  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.070s	user 0.025s	sys 0.029s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":26621,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:30.184259  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:30.196148  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.196887  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:30.402689  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.205s	user 0.125s	sys 0.080s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877105,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":304,"lbm_read_time_us":13640,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35675,"lbm_writes_lt_1ms":643,"mutex_wait_us":37,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":3000}
I20260812 06:19:30.403717  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=15.087375
I20260812 06:19:30.463826  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.060s	user 0.027s	sys 0.027s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":28162,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":412,"reinsert_count":0,"update_count":2050}
I20260812 06:19:30.464558  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:30.481215  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.016s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4348806,"delete_count":0,"lbm_write_time_us":6924,"lbm_writes_lt_1ms":109,"reinsert_count":0,"update_count":530}
I20260812 06:19:30.481606  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:30.490494  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3446255,"delete_count":0,"lbm_write_time_us":3560,"lbm_writes_lt_1ms":87,"reinsert_count":0,"update_count":420}
I20260812 06:19:30.490971  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:30.686321  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.195s	user 0.123s	sys 0.071s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877204,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":628,"lbm_read_time_us":15607,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30514,"lbm_writes_lt_1ms":643,"mutex_wait_us":323,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":25344,"update_count":3000}
I20260812 06:19:30.687036  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:30.749904  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.063s	user 0.049s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25297,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.750432  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:30.761359  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4310,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:30.761921  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:30.937842  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.176s	user 0.119s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":362,"lbm_read_time_us":13028,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29239,"lbm_writes_lt_1ms":543,"mutex_wait_us":18,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8704,"update_count":2500}
I20260812 06:19:30.938529  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:30.996583  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.058s	user 0.038s	sys 0.018s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20492,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:30.997131  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:31.008013  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.008445  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:31.188593  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.180s	user 0.114s	sys 0.060s 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":887,"lbm_read_time_us":13613,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28138,"lbm_writes_lt_1ms":543,"mutex_wait_us":339,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:31.189039  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:31.253866  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.065s	user 0.041s	sys 0.022s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":25223,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.254379  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:31.265219  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4226,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.265689  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushMRSOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:31.297329  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushMRSOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":220,"dirs.run_wall_time_us":1534,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1535,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:31.298048  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:31.487308  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.189s	user 0.128s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774693,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":567,"lbm_read_time_us":13465,"lbm_reads_lt_1ms":564,"lbm_write_time_us":29291,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":22784,"update_count":2500}
I20260812 06:19:31.488168  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling LogGCOp(a195840ef6b74fb68318150997ad5629): free 120100336 bytes of WAL
I20260812 06:19:31.488485  3402 log_reader.cc:385] T a195840ef6b74fb68318150997ad5629: removed 12 log segments from log reader
I20260812 06:19:31.488581  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000015 (ops 70-74)
I20260812 06:19:31.488654  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000016 (ops 75-79)
I20260812 06:19:31.488721  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000017 (ops 80-84)
I20260812 06:19:31.488776  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000018 (ops 85-89)
I20260812 06:19:31.488857  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000019 (ops 90-94)
I20260812 06:19:31.488924  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000020 (ops 95-98)
I20260812 06:19:31.488991  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000021 (ops 99-103)
I20260812 06:19:31.489063  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000022 (ops 104-108)
I20260812 06:19:31.489136  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000023 (ops 109-112)
I20260812 06:19:31.489205  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000024 (ops 113-117)
I20260812 06:19:31.489260  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000025 (ops 118-122)
I20260812 06:19:31.489316  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000026 (ops 123-126)
I20260812 06:19:31.517258  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: LogGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.029s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:19:31.517699  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629): 463 bytes on disk
I20260812 06:19:31.518462  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:19:31.519145  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=18.063937
I20260812 06:19:31.589939  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.071s	user 0.038s	sys 0.031s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28070,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:31.590492  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:31.602401  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4238,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.602954  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:31.795727  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.193s	user 0.120s	sys 0.072s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877104,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1108,"lbm_read_time_us":15811,"lbm_reads_lt_1ms":672,"lbm_write_time_us":30322,"lbm_writes_lt_1ms":643,"mutex_wait_us":258,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3000}
I20260812 06:19:31.796418  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:31.850987  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.054s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23955,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:31.851683  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:31.879830  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.028s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6094,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.880335  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:31.890727  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4323,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:31.891238  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:32.090150  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.199s	user 0.114s	sys 0.083s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877221,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":262,"lbm_read_time_us":14082,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31210,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:19:32.091625  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=16.079562
I20260812 06:19:32.160108  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.068s	user 0.028s	sys 0.030s Metrics: {"bytes_written":17681652,"delete_count":0,"lbm_write_time_us":28063,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":432,"reinsert_count":0,"update_count":2155}
I20260812 06:19:32.160681  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=5.165500
I20260812 06:19:32.180596  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.020s	user 0.014s	sys 0.004s Metrics: {"bytes_written":6933335,"delete_count":0,"lbm_write_time_us":8230,"lbm_writes_lt_1ms":172,"reinsert_count":0,"update_count":845}
I20260812 06:19:32.181169  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:32.391382  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.210s	user 0.136s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877109,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1329,"lbm_read_time_us":14907,"lbm_reads_lt_1ms":664,"lbm_write_time_us":34173,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":3000}
I20260812 06:19:32.392138  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=18.063937
I20260812 06:19:32.460263  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.068s	user 0.033s	sys 0.021s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":25912,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:32.460780  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:32.471875  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4263,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.472774  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:32.671142  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.198s	user 0.122s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877102,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1209,"lbm_read_time_us":15545,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31912,"lbm_writes_lt_1ms":643,"mutex_wait_us":307,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4608,"update_count":3000}
I20260812 06:19:32.671954  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=14.095187
I20260812 06:19:32.721719  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.050s	user 0.036s	sys 0.012s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":21233,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:32.722546  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:32.737696  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5677,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.738300  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushMRSOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:32.765439  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushMRSOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193505,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":221,"dirs.run_wall_time_us":1286,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1967,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:32.766140  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling LogGCOp(a195840ef6b74fb68318150997ad5629): free 121006640 bytes of WAL
I20260812 06:19:32.766420  3402 log_reader.cc:385] T a195840ef6b74fb68318150997ad5629: removed 12 log segments from log reader
I20260812 06:19:32.766479  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000027 (ops 127-131)
I20260812 06:19:32.766520  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000028 (ops 132-136)
I20260812 06:19:32.766554  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000029 (ops 137-141)
I20260812 06:19:32.766578  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000030 (ops 142-146)
I20260812 06:19:32.766606  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000031 (ops 147-151)
I20260812 06:19:32.766634  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000032 (ops 152-156)
I20260812 06:19:32.766659  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000033 (ops 157-161)
I20260812 06:19:32.766692  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000034 (ops 162-166)
I20260812 06:19:32.766718  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000035 (ops 167-170)
I20260812 06:19:32.766741  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000036 (ops 171-175)
I20260812 06:19:32.766769  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000037 (ops 176-180)
I20260812 06:19:32.766793  3402 log.cc:1079] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: Deleting log segment in path: /tmp/dist-test-taskFbDj6l/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515562578146-3097-0/minicluster-data/ts-0-root/wals/a195840ef6b74fb68318150997ad5629/wal-000000038 (ops 181-185)
I20260812 06:19:32.792371  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: LogGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.026s	user 0.003s	sys 0.022s Metrics: {}
I20260812 06:19:32.792800  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:32.810243  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4215,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.810738  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629): 462 bytes on disk
I20260812 06:19:32.811146  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: UndoDeltaBlockGCOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:19:32.811676  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:32.822495  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:32.822937  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:33.044831  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.222s	user 0.154s	sys 0.067s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979751,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":537,"lbm_read_time_us":16419,"lbm_reads_lt_1ms":774,"lbm_write_time_us":39114,"lbm_writes_lt_1ms":743,"mutex_wait_us":73,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11392,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:19:33.048533  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=18.063937
I20260812 06:19:33.103928  3097 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.955s	user 1.789s	sys 0.189s
I20260812 06:19:33.109802  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.061s	user 0.044s	sys 0.016s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":28650,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:33.110455  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629): perf score=2.188937
I20260812 06:19:33.125964  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: FlushDeltaMemStoresOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.015s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:33.126633  3467 maintenance_manager.cc:419] P f6b255a346e64e41bdc00183efd13bd7: Scheduling MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629): perf score=1.000000
I20260812 06:19:33.140861  3097 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.036s	user 0.002s	sys 0.000s
I20260812 06:19:33.141361  3097 tablet_server.cc:179] TabletServer@127.3.6.65:0 shutting down...
I20260812 06:19:33.294097  3402 maintenance_manager.cc:643] P f6b255a346e64e41bdc00183efd13bd7: MajorDeltaCompactionOp(a195840ef6b74fb68318150997ad5629) complete. Timing: real 0.167s	user 0.131s	sys 0.036s Metrics: {"cfile_cache_hit":30,"cfile_cache_hit_bytes":4262390,"cfile_cache_miss":602,"cfile_cache_miss_bytes":24614713,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":396,"lbm_read_time_us":13667,"lbm_reads_lt_1ms":618,"lbm_write_time_us":30656,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":57472,"update_count":3000}
I20260812 06:19:33.294896  3097 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:33.295167  3097 tablet_replica.cc:333] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7: stopping tablet replica
I20260812 06:19:33.295336  3097 raft_consensus.cc:2243] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.295521  3097 raft_consensus.cc:2272] T a195840ef6b74fb68318150997ad5629 P f6b255a346e64e41bdc00183efd13bd7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.311221  3097 tablet_server.cc:196] TabletServer@127.3.6.65:0 shutdown complete.
I20260812 06:19:33.346930  3097 master.cc:562] Master@127.3.6.126:36741 shutting down...
I20260812 06:19:33.350078  3097 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:33.350234  3097 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:33.350286  3097 tablet_replica.cc:333] T 00000000000000000000000000000000 P 20df7d8ccfe34643bd479546366dbc27: stopping tablet replica
I20260812 06:19:33.362641  3097 master.cc:584] Master@127.3.6.126:36741 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5535 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10864 ms total)

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