[==========] 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:56.543314  3937 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.216.126:33407
I20260812 06:19:56.544449  3937 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:56.545166  3937 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.552265  3946 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:56.552452  3944 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:56.552278  3937 server_base.cc:1061] running on GCE node
W20260812 06:19:56.552738  3949 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:56.553295  3937 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.553423  3937 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:56.553478  3937 hybrid_clock.cc:648] HybridClock initialized: now 1786515596553474 us; error 0 us; skew 500 ppm
I20260812 06:19:56.555491  3937 webserver.cc:533] Webserver started at http://127.3.216.126:37683/ using document root <none> and password file <none>
I20260812 06:19:56.556123  3937 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.556190  3937 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.556469  3937 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.558280  3937 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/master-0-root/instance:
uuid: "6dc4dc53fc9543e89d074f0153472745"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-65mx"
I20260812 06:19:56.562224  3937 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:56.564383  3955 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:56.565497  3937 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.001s
I20260812 06:19:56.565629  3937 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/master-0-root
uuid: "6dc4dc53fc9543e89d074f0153472745"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-65mx"
I20260812 06:19:56.565743  3937 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-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:56.582039  3937 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.582747  3937 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:56.582942  3937 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.591180  3937 rpc_server.cc:307] RPC server started. Bound to: 127.3.216.126:33407
I20260812 06:19:56.591208  4013 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.216.126:33407 every 8 connection(s)
I20260812 06:19:56.593860  4014 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:56.599962  4014 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: Bootstrap starting.
I20260812 06:19:56.602707  4014 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.603766  4014 log.cc:826] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:56.605984  4014 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: No bootstrap required, opened a new log
I20260812 06:19:56.609083  4014 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER }
I20260812 06:19:56.609288  4014 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.609401  4014 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6dc4dc53fc9543e89d074f0153472745, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.610090  4014 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [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: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER }
I20260812 06:19:56.610280  4014 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.610368  4014 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.610554  4014 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.611500  4014 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER }
I20260812 06:19:56.612008  4014 leader_election.cc:304] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [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: 6dc4dc53fc9543e89d074f0153472745; no voters: 
I20260812 06:19:56.612380  4014 leader_election.cc:290] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.612651  4017 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.612950  4017 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 1 LEADER]: Becoming Leader. State: Replica: 6dc4dc53fc9543e89d074f0153472745, State: Running, Role: LEADER
I20260812 06:19:56.613384  4017 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [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: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER }
I20260812 06:19:56.613655  4014 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:56.615621  4019 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6dc4dc53fc9543e89d074f0153472745. Latest consensus state: current_term: 1 leader_uuid: "6dc4dc53fc9543e89d074f0153472745" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER } }
I20260812 06:19:56.615656  4018 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6dc4dc53fc9543e89d074f0153472745" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6dc4dc53fc9543e89d074f0153472745" member_type: VOTER } }
I20260812 06:19:56.615784  4019 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.615784  4018 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:56.616454  3937 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:56.618625  4033 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:56.618698  4033 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:56.618789  4029 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:56.619555  4029 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:56.624495  4029 catalog_manager.cc:1383] Generated new cluster ID: e489637172e349b0877b8777d54a8ada
I20260812 06:19:56.624615  4029 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:56.645046  4029 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:56.646301  4029 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:56.655187  4029 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: Generated new TSK 0
I20260812 06:19:56.656061  4029 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:56.681550  3937 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:56.684243  4038 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:56.684355  4039 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:56.684336  4041 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:56.685066  3937 server_base.cc:1061] running on GCE node
I20260812 06:19:56.685277  3937 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:56.685338  3937 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:56.685382  3937 hybrid_clock.cc:648] HybridClock initialized: now 1786515596685381 us; error 0 us; skew 500 ppm
I20260812 06:19:56.686403  3937 webserver.cc:533] Webserver started at http://127.3.216.65:43789/ using document root <none> and password file <none>
I20260812 06:19:56.686604  3937 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:56.686676  3937 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:56.686759  3937 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:56.687196  3937 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/instance:
uuid: "94ef0729d01f4cf3ad14de3794e535f5"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-65mx"
I20260812 06:19:56.688871  3937 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:56.689956  4047 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:56.690218  3937 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:56.690295  3937 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root
uuid: "94ef0729d01f4cf3ad14de3794e535f5"
format_stamp: "Formatted at 2026-08-12 06:19:56 on dist-test-slave-65mx"
I20260812 06:19:56.690388  3937 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-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:56.714682  3937 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:56.715665  3937 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:56.716364  3937 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:56.717377  3937 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:56.717432  3937 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.717497  3937 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:56.717540  3937 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:56.724478  3937 rpc_server.cc:307] RPC server started. Bound to: 127.3.216.65:46169
I20260812 06:19:56.724566  4120 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.216.65:46169 every 8 connection(s)
I20260812 06:19:56.740432  4121 heartbeater.cc:344] Connected to a master server at 127.3.216.126:33407
I20260812 06:19:56.740782  4121 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:56.741282  4121 heartbeater.cc:507] Master 127.3.216.126:33407 requested a full tablet report, sending...
I20260812 06:19:56.743008  3976 ts_manager.cc:194] Registered new tserver with Master: 94ef0729d01f4cf3ad14de3794e535f5 (127.3.216.65:46169)
I20260812 06:19:56.743239  3937 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.018057063s
I20260812 06:19:56.744755  3976 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:50764
I20260812 06:19:56.755107  3976 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:50766:
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:56.773175  4081 tablet_service.cc:1511] Processing CreateTablet for tablet bedd85b4d21c40fdbabf1b536ed0b80b (DEFAULT_TABLE table=heavy-update-compaction-test [id=e0ecdae0c7764904be6f3b2c5d87d452]), partition=
I20260812 06:19:56.773675  4081 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet bedd85b4d21c40fdbabf1b536ed0b80b. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:56.776232  4134 tablet_bootstrap.cc:492] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Bootstrap starting.
I20260812 06:19:56.777974  4134 tablet_bootstrap.cc:654] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:56.779287  4134 tablet_bootstrap.cc:492] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: No bootstrap required, opened a new log
I20260812 06:19:56.779425  4134 ts_tablet_manager.cc:1403] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:56.779918  4134 raft_consensus.cc:359] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94ef0729d01f4cf3ad14de3794e535f5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 46169 } }
I20260812 06:19:56.780049  4134 raft_consensus.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:56.780099  4134 raft_consensus.cc:740] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 94ef0729d01f4cf3ad14de3794e535f5, State: Initialized, Role: FOLLOWER
I20260812 06:19:56.780275  4134 consensus_queue.cc:260] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [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: "94ef0729d01f4cf3ad14de3794e535f5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 46169 } }
I20260812 06:19:56.780390  4134 raft_consensus.cc:399] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:56.780439  4134 raft_consensus.cc:493] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:56.780493  4134 raft_consensus.cc:3060] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:56.781299  4134 raft_consensus.cc:515] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94ef0729d01f4cf3ad14de3794e535f5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 46169 } }
I20260812 06:19:56.781461  4134 leader_election.cc:304] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [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: 94ef0729d01f4cf3ad14de3794e535f5; no voters: 
I20260812 06:19:56.781701  4134 leader_election.cc:290] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:56.781831  4137 raft_consensus.cc:2804] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:56.782126  4137 raft_consensus.cc:697] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 1 LEADER]: Becoming Leader. State: Replica: 94ef0729d01f4cf3ad14de3794e535f5, State: Running, Role: LEADER
I20260812 06:19:56.782127  4134 ts_tablet_manager.cc:1434] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Time spent starting tablet: real 0.003s	user 0.000s	sys 0.003s
I20260812 06:19:56.782410  4137 consensus_queue.cc:237] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [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: "94ef0729d01f4cf3ad14de3794e535f5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 46169 } }
I20260812 06:19:56.782629  4121 heartbeater.cc:499] Master 127.3.216.126:33407 was elected leader, sending a full tablet report...
I20260812 06:19:56.785475  3976 catalog_manager.cc:5719] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 94ef0729d01f4cf3ad14de3794e535f5 (127.3.216.65). New cstate: current_term: 1 leader_uuid: "94ef0729d01f4cf3ad14de3794e535f5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "94ef0729d01f4cf3ad14de3794e535f5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 46169 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:56.858325  3937 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.063s	user 0.020s	sys 0.008s
I20260812 06:19:56.979351  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=11.117440
I20260812 06:19:57.156440  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.177s	user 0.127s	sys 0.036s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":327,"delete_count":0,"dirs.queue_time_us":101,"dirs.run_cpu_time_us":253,"dirs.run_wall_time_us":1324,"drs_written":1,"lbm_read_time_us":110,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38298,"lbm_writes_lt_1ms":557,"peak_mem_usage":0,"reinsert_count":0,"rows_written":103,"thread_start_us":188,"threads_started":1,"update_count":1450}
I20260812 06:19:57.158002  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): free 11976772 bytes of WAL
I20260812 06:19:57.158418  4052 log_reader.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b: removed 1 log segments from log reader
I20260812 06:19:57.158560  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000001 (ops 1-6)
I20260812 06:19:57.162149  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:57.162683  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): 8616791 bytes on disk
I20260812 06:19:57.163462  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4}
I20260812 06:19:57.164072  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:57.177465  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5222,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.177929  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:57.326265  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.148s	user 0.102s	sys 0.036s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20221071,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1283,"lbm_read_time_us":9195,"lbm_reads_lt_1ms":454,"lbm_write_time_us":27006,"lbm_writes_lt_1ms":433,"mutex_wait_us":378,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":9728,"thread_start_us":341,"threads_started":5,"update_count":1950}
I20260812 06:19:57.327064  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:57.376919  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.050s	user 0.040s	sys 0.000s Metrics: {"bytes_written":12307497,"delete_count":0,"lbm_write_time_us":17359,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.377491  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:57.388908  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.389489  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:57.521517  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.132s	user 0.100s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631319,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":172,"lbm_read_time_us":10044,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24216,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2000}
I20260812 06:19:57.522172  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:57.577531  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.055s	user 0.032s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18990,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.578099  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:57.590266  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.590830  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:57.738695  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.148s	user 0.099s	sys 0.048s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":170,"lbm_read_time_us":12313,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24513,"lbm_writes_lt_1ms":443,"mutex_wait_us":53,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":23040,"update_count":2000}
I20260812 06:19:57.739387  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:57.788259  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.049s	user 0.029s	sys 0.008s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16988,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.788789  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:57.802371  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.013s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4567,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.802991  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:57.934573  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.131s	user 0.111s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1029,"lbm_read_time_us":9907,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25862,"lbm_writes_lt_1ms":443,"mutex_wait_us":361,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13952,"update_count":2000}
I20260812 06:19:57.935149  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:57.987071  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.052s	user 0.031s	sys 0.007s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17909,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:57.987628  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:57.998888  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4187,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:57.999548  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:58.125173  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.125s	user 0.086s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":363,"lbm_read_time_us":9009,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23610,"lbm_writes_lt_1ms":443,"mutex_wait_us":86,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:58.125829  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:58.173252  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.047s	user 0.031s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17128,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.173810  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:58.185058  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4148,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.185668  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:58.313026  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.127s	user 0.098s	sys 0.028s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":727,"lbm_read_time_us":9974,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23387,"lbm_writes_lt_1ms":443,"mutex_wait_us":52,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2000}
I20260812 06:19:58.313707  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:58.365676  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.052s	user 0.025s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18905,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.366389  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:58.377614  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.378118  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:58.527863  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.150s	user 0.118s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":223,"lbm_read_time_us":11116,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25643,"lbm_writes_lt_1ms":443,"mutex_wait_us":47,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:19:58.528621  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:58.577355  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.048s	user 0.029s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18386,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:58.578004  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:58.593794  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5951,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:58.594266  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:58.629838  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.035s	user 0.030s	sys 0.004s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":214,"dirs.run_wall_time_us":1419,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1999,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:58.630718  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): free 133024358 bytes of WAL
I20260812 06:19:58.630966  4052 log_reader.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b: removed 13 log segments from log reader
I20260812 06:19:58.631026  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000002 (ops 7-11)
I20260812 06:19:58.631094  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000003 (ops 12-16)
I20260812 06:19:58.631155  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000004 (ops 17-21)
I20260812 06:19:58.631204  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000005 (ops 22-26)
I20260812 06:19:58.631247  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000006 (ops 27-31)
I20260812 06:19:58.631291  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000007 (ops 32-36)
I20260812 06:19:58.631335  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000008 (ops 37-41)
I20260812 06:19:58.631376  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000009 (ops 42-46)
I20260812 06:19:58.631419  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000010 (ops 47-50)
I20260812 06:19:58.631460  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000011 (ops 51-55)
I20260812 06:19:58.631503  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000012 (ops 56-60)
I20260812 06:19:58.631546  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000013 (ops 61-65)
I20260812 06:19:58.631585  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000014 (ops 66-70)
I20260812 06:19:58.662249  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:19:58.662760  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=3.181125
I20260812 06:19:58.696182  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.033s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4614,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:58.696813  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:58.711011  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5505,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:58.711733  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): 482 bytes on disk
I20260812 06:19:58.712378  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:58.712909  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:58.946280  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.233s	user 0.144s	sys 0.076s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836361,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":315,"lbm_read_time_us":15284,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39636,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7552,"thread_start_us":110,"threads_started":1,"update_count":3000}
I20260812 06:19:58.947185  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=14.095187
I20260812 06:19:59.012200  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.065s	user 0.037s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21551,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.012846  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:59.024533  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4632,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.025077  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:59.212754  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.187s	user 0.151s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1092,"lbm_read_time_us":14013,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33346,"lbm_writes_lt_1ms":543,"mutex_wait_us":578,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2500}
I20260812 06:19:59.213436  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=11.118625
I20260812 06:19:59.247762  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.034s	user 0.022s	sys 0.008s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14488,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:59.248422  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:59.261772  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.013s	user 0.006s	sys 0.006s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4692,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:59.262348  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:59.399922  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.137s	user 0.091s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631303,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":246,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25113,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2000}
I20260812 06:19:59.400663  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:59.445773  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.045s	user 0.031s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":20055,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.446267  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:59.458757  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4471,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.459296  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:59.590756  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.131s	user 0.102s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631313,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":310,"lbm_read_time_us":8481,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25993,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":68608,"update_count":2000}
I20260812 06:19:59.591351  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:59.635195  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.044s	user 0.021s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15652,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.635795  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:59.648408  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4579,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.648953  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:59.776515  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.127s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631311,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":214,"lbm_read_time_us":10030,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22924,"lbm_writes_lt_1ms":443,"mutex_wait_us":33,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:19:59.777257  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:19:59.827304  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.050s	user 0.033s	sys 0.014s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":17549,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:59.827924  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:19:59.840075  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4686,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:59.840660  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:19:59.996409  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.156s	user 0.102s	sys 0.049s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631310,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":242,"lbm_read_time_us":11010,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26638,"lbm_writes_lt_1ms":443,"mutex_wait_us":72,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:59.997159  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:20:00.045035  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.047s	user 0.016s	sys 0.027s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18071,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.045686  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:00.057320  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.009s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4089,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.057905  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:00.186327  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20631312,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1534,"lbm_read_time_us":9325,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26005,"lbm_writes_lt_1ms":443,"mutex_wait_us":326,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.186993  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:20:00.231498  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.044s	user 0.030s	sys 0.008s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18017,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:00.232131  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:00.243847  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4375,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.244493  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:00.276032  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":267,"dirs.run_wall_time_us":1524,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1793,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:00.277081  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): free 128867464 bytes of WAL
I20260812 06:20:00.277379  4052 log_reader.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b: removed 13 log segments from log reader
I20260812 06:20:00.277468  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000015 (ops 71-75)
I20260812 06:20:00.277535  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000016 (ops 76-80)
I20260812 06:20:00.277580  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000017 (ops 81-84)
I20260812 06:20:00.277635  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000018 (ops 85-89)
I20260812 06:20:00.277674  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000019 (ops 90-94)
I20260812 06:20:00.277712  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000020 (ops 95-98)
I20260812 06:20:00.277750  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000021 (ops 99-103)
I20260812 06:20:00.277786  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000022 (ops 104-108)
I20260812 06:20:00.277824  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000023 (ops 109-113)
I20260812 06:20:00.277863  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000024 (ops 114-118)
I20260812 06:20:00.277902  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000025 (ops 119-123)
I20260812 06:20:00.277940  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000026 (ops 124-128)
I20260812 06:20:00.277984  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000027 (ops 129-132)
I20260812 06:20:00.310699  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:20:00.311292  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): 482 bytes on disk
I20260812 06:20:00.311966  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":79,"lbm_reads_lt_1ms":4}
I20260812 06:20:00.312685  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=3.181125
I20260812 06:20:00.332196  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":5087238,"delete_count":0,"lbm_write_time_us":8159,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:20:00.332782  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.196750
I20260812 06:20:00.343710  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":3812,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:20:00.344729  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:00.526414  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.181s	user 0.153s	sys 0.028s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28836348,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":781,"lbm_read_time_us":12393,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37437,"lbm_writes_lt_1ms":643,"mutex_wait_us":326,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6528,"thread_start_us":79,"threads_started":1,"update_count":3000}
I20260812 06:20:00.527202  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=14.095187
I20260812 06:20:00.581205  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.054s	user 0.038s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":25412,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.581773  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:00.601823  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.020s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.602463  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:00.756819  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.154s	user 0.115s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733722,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":373,"lbm_read_time_us":9556,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28675,"lbm_writes_lt_1ms":543,"mutex_wait_us":68,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3456,"update_count":2500}
I20260812 06:20:00.758064  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=14.095187
I20260812 06:20:00.834376  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.076s	user 0.021s	sys 0.040s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":27687,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:00.834975  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:00.847215  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4157,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:00.848110  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:01.030821  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.182s	user 0.146s	sys 0.034s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":765,"lbm_read_time_us":12254,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32536,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:20:01.031296  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=14.095187
I20260812 06:20:01.092638  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.061s	user 0.023s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21890,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.093261  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:01.107357  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4664,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.107939  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:01.281383  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.173s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733723,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":11925,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29543,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":2500}
I20260812 06:20:01.282017  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=14.095187
I20260812 06:20:01.342788  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.061s	user 0.023s	sys 0.035s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":22098,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:01.343410  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:01.355156  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.355691  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:01.542558  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.187s	user 0.114s	sys 0.068s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24733720,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":565,"lbm_read_time_us":12909,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32208,"lbm_writes_lt_1ms":543,"mutex_wait_us":290,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:01.543205  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=11.118625
I20260812 06:20:01.580798  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.037s	user 0.030s	sys 0.007s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":14771,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:20:01.581576  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:01.612859  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.031s	user 0.005s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4139,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.613480  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:01.624054  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:01.624701  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:01.793761  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.169s	user 0.108s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24733836,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1315,"lbm_read_time_us":12982,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27759,"lbm_writes_lt_1ms":543,"mutex_wait_us":493,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:01.794577  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=10.126437
I20260812 06:20:01.830863  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.036s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15516,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:01.831537  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=2.188937
I20260812 06:20:01.848869  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.017s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6553,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:01.849354  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:01.875700  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushMRSOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.026s	user 0.021s	sys 0.004s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":311,"dirs.run_wall_time_us":1597,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1521,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:01.876399  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): free 121459761 bytes of WAL
I20260812 06:20:01.876672  4052 log_reader.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b: removed 12 log segments from log reader
I20260812 06:20:01.876734  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000028 (ops 133-137)
I20260812 06:20:01.876789  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000029 (ops 138-142)
I20260812 06:20:01.876847  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000030 (ops 143-147)
I20260812 06:20:01.876892  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000031 (ops 148-152)
I20260812 06:20:01.876933  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000032 (ops 153-157)
I20260812 06:20:01.876984  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000033 (ops 158-162)
I20260812 06:20:01.877022  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000034 (ops 163-167)
I20260812 06:20:01.877058  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000035 (ops 168-172)
I20260812 06:20:01.877125  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000036 (ops 173-177)
I20260812 06:20:01.877170  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000037 (ops 178-182)
I20260812 06:20:01.877206  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000038 (ops 183-187)
I20260812 06:20:01.877243  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000039 (ops 188-192)
I20260812 06:20:01.906353  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.030s	user 0.003s	sys 0.023s Metrics: {}
I20260812 06:20:01.915194  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): 483 bytes on disk
I20260812 06:20:01.915810  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: UndoDeltaBlockGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":80,"lbm_reads_lt_1ms":4}
I20260812 06:20:01.916641  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=6.157687
I20260812 06:20:01.947337  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: FlushDeltaMemStoresOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.030s	user 0.019s	sys 0.008s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":13049,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:20:01.947908  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b): free 11564893 bytes of WAL
I20260812 06:20:01.948206  4052 log_reader.cc:385] T bedd85b4d21c40fdbabf1b536ed0b80b: removed 1 log segments from log reader
I20260812 06:20:01.948271  4052 log.cc:1079] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/bedd85b4d21c40fdbabf1b536ed0b80b/wal-000000040 (ops 193-196)
I20260812 06:20:01.951524  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: LogGCOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.003s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:20:01.951890  4122 maintenance_manager.cc:419] P 94ef0729d01f4cf3ad14de3794e535f5: Scheduling MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b): perf score=1.000000
I20260812 06:20:02.021747  3937 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.163s	user 1.896s	sys 0.147s
I20260812 06:20:02.113103  3937 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.091s	user 0.003s	sys 0.000s
I20260812 06:20:02.113759  3937 tablet_server.cc:179] TabletServer@127.3.216.65:0 shutting down...
I20260812 06:20:02.133112  4052 maintenance_manager.cc:643] P 94ef0729d01f4cf3ad14de3794e535f5: MajorDeltaCompactionOp(bedd85b4d21c40fdbabf1b536ed0b80b) complete. Timing: real 0.181s	user 0.113s	sys 0.068s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28836257,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1021,"lbm_read_time_us":11821,"lbm_reads_lt_1ms":665,"lbm_write_time_us":29775,"lbm_writes_lt_1ms":643,"mutex_wait_us":314,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":15744,"thread_start_us":86,"threads_started":1,"update_count":3000}
I20260812 06:20:02.134191  3937 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:02.134790  3937 tablet_replica.cc:333] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5: stopping tablet replica
I20260812 06:20:02.135036  3937 raft_consensus.cc:2243] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.135317  3937 raft_consensus.cc:2272] T bedd85b4d21c40fdbabf1b536ed0b80b P 94ef0729d01f4cf3ad14de3794e535f5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.152384  3937 tablet_server.cc:196] TabletServer@127.3.216.65:0 shutdown complete.
I20260812 06:20:02.184690  3937 master.cc:562] Master@127.3.216.126:33407 shutting down...
I20260812 06:20:02.189006  3937 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:02.189230  3937 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:02.189314  3937 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6dc4dc53fc9543e89d074f0153472745: stopping tablet replica
I20260812 06:20:02.201867  3937 master.cc:584] Master@127.3.216.126:33407 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5751 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:20:02.306735  3937 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.3.216.126:45429
I20260812 06:20:02.307190  3937 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.310395  4157 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:20:02.310395  3937 server_base.cc:1061] running on GCE node
W20260812 06:20:02.310578  4160 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:20:02.310416  4158 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:20:02.310968  3937 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.311024  3937 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:20:02.311040  3937 hybrid_clock.cc:648] HybridClock initialized: now 1786515602311040 us; error 0 us; skew 500 ppm
I20260812 06:20:02.312048  3937 webserver.cc:533] Webserver started at http://127.3.216.126:39251/ using document root <none> and password file <none>
I20260812 06:20:02.312258  3937 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.312319  3937 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.312407  3937 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.312879  3937 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/master-0-root/instance:
uuid: "3f236870c955462b854ae3f5a45d1cff"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-65mx"
I20260812 06:20:02.314544  3937 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:20:02.315604  4165 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:20:02.315927  3937 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:20:02.316004  3937 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/master-0-root
uuid: "3f236870c955462b854ae3f5a45d1cff"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-65mx"
I20260812 06:20:02.316059  3937 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-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:20:02.336814  3937 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.337325  3937 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.341831  3937 rpc_server.cc:307] RPC server started. Bound to: 127.3.216.126:45429
I20260812 06:20:02.347307  4220 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.216.126:45429 every 8 connection(s)
I20260812 06:20:02.349283  4221 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:20:02.351184  4221 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff: Bootstrap starting.
I20260812 06:20:02.351933  4221 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.353111  4221 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff: No bootstrap required, opened a new log
I20260812 06:20:02.353538  4221 raft_consensus.cc:359] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER }
I20260812 06:20:02.353646  4221 raft_consensus.cc:385] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.353672  4221 raft_consensus.cc:740] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 3f236870c955462b854ae3f5a45d1cff, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.353806  4221 consensus_queue.cc:260] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [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: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER }
I20260812 06:20:02.353873  4221 raft_consensus.cc:399] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.353896  4221 raft_consensus.cc:493] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.353935  4221 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.354705  4221 raft_consensus.cc:515] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER }
I20260812 06:20:02.354839  4221 leader_election.cc:304] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [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: 3f236870c955462b854ae3f5a45d1cff; no voters: 
I20260812 06:20:02.355027  4221 leader_election.cc:290] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.355183  4227 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.355423  4227 raft_consensus.cc:697] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 1 LEADER]: Becoming Leader. State: Replica: 3f236870c955462b854ae3f5a45d1cff, State: Running, Role: LEADER
I20260812 06:20:02.355654  4227 consensus_queue.cc:237] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [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: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER }
I20260812 06:20:02.355715  4221 sys_catalog.cc:565] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:20:02.356132  4229 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [sys.catalog]: SysCatalogTable state changed. Reason: New leader 3f236870c955462b854ae3f5a45d1cff. Latest consensus state: current_term: 1 leader_uuid: "3f236870c955462b854ae3f5a45d1cff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER } }
I20260812 06:20:02.356231  4229 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.356119  4228 sys_catalog.cc:455] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "3f236870c955462b854ae3f5a45d1cff" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "3f236870c955462b854ae3f5a45d1cff" member_type: VOTER } }
I20260812 06:20:02.356367  4228 sys_catalog.cc:458] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [sys.catalog]: This master's current role is: LEADER
I20260812 06:20:02.356859  4232 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:20:02.357630  4232 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:20:02.358021  3937 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:20:02.359567  4232 catalog_manager.cc:1383] Generated new cluster ID: 0d5f15f3fc714344963e79d6136aba7f
I20260812 06:20:02.359654  4232 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:20:02.366408  4232 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:20:02.367030  4232 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:20:02.372390  4232 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff: Generated new TSK 0
I20260812 06:20:02.372642  4232 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:20:02.374505  3937 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:20:02.376739  4247 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:20:02.376752  4250 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:20:02.376827  4248 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:20:02.377154  3937 server_base.cc:1061] running on GCE node
I20260812 06:20:02.377370  3937 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:20:02.377427  3937 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:20:02.377461  3937 hybrid_clock.cc:648] HybridClock initialized: now 1786515602377461 us; error 0 us; skew 500 ppm
I20260812 06:20:02.378389  3937 webserver.cc:533] Webserver started at http://127.3.216.65:42421/ using document root <none> and password file <none>
I20260812 06:20:02.378597  3937 fs_manager.cc:362] Metadata directory not provided
I20260812 06:20:02.378674  3937 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:20:02.378769  3937 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:20:02.379210  3937 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/instance:
uuid: "8d50af6462af44e09ee22127420737d5"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-65mx"
I20260812 06:20:02.381063  3937 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:20:02.382129  4255 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:20:02.382360  3937 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:20:02.382454  3937 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root
uuid: "8d50af6462af44e09ee22127420737d5"
format_stamp: "Formatted at 2026-08-12 06:20:02 on dist-test-slave-65mx"
I20260812 06:20:02.382546  3937 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-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:20:02.401609  3937 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:20:02.402205  3937 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:20:02.402601  3937 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:20:02.403153  3937 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:20:02.403223  3937 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.403290  3937 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:20:02.403347  3937 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:20:02.408780  3937 rpc_server.cc:307] RPC server started. Bound to: 127.3.216.65:33371
I20260812 06:20:02.409050  4326 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.3.216.65:33371 every 8 connection(s)
I20260812 06:20:02.420855  4327 heartbeater.cc:344] Connected to a master server at 127.3.216.126:45429
I20260812 06:20:02.421021  4327 heartbeater.cc:461] Registering TS with master...
I20260812 06:20:02.421307  4327 heartbeater.cc:507] Master 127.3.216.126:45429 requested a full tablet report, sending...
I20260812 06:20:02.422101  4182 ts_manager.cc:194] Registered new tserver with Master: 8d50af6462af44e09ee22127420737d5 (127.3.216.65:33371)
I20260812 06:20:02.422881  4182 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60974
I20260812 06:20:02.422894  3937 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.0135377s
I20260812 06:20:02.430877  4182 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60978:
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:20:02.441008  4286 tablet_service.cc:1511] Processing CreateTablet for tablet 1f89eebd03dd4d1d94efa6b50cd34f7d (DEFAULT_TABLE table=heavy-update-compaction-test [id=612360dac5aa460990051a36fb1b7b4b]), partition=
I20260812 06:20:02.441309  4286 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 1f89eebd03dd4d1d94efa6b50cd34f7d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:20:02.443913  4340 tablet_bootstrap.cc:492] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Bootstrap starting.
I20260812 06:20:02.445024  4340 tablet_bootstrap.cc:654] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Neither blocks nor log segments found. Creating new log.
I20260812 06:20:02.446399  4340 tablet_bootstrap.cc:492] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: No bootstrap required, opened a new log
I20260812 06:20:02.446611  4340 ts_tablet_manager.cc:1403] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:20:02.447238  4340 raft_consensus.cc:359] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d50af6462af44e09ee22127420737d5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 33371 } }
I20260812 06:20:02.447337  4340 raft_consensus.cc:385] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:20:02.447360  4340 raft_consensus.cc:740] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8d50af6462af44e09ee22127420737d5, State: Initialized, Role: FOLLOWER
I20260812 06:20:02.447558  4340 consensus_queue.cc:260] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [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: "8d50af6462af44e09ee22127420737d5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 33371 } }
I20260812 06:20:02.447638  4340 raft_consensus.cc:399] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:20:02.447664  4340 raft_consensus.cc:493] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:20:02.447728  4340 raft_consensus.cc:3060] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:20:02.448621  4340 raft_consensus.cc:515] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d50af6462af44e09ee22127420737d5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 33371 } }
I20260812 06:20:02.448791  4340 leader_election.cc:304] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [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: 8d50af6462af44e09ee22127420737d5; no voters: 
I20260812 06:20:02.449038  4340 leader_election.cc:290] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:20:02.449213  4342 raft_consensus.cc:2804] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:20:02.449393  4340 ts_tablet_manager.cc:1434] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:20:02.449434  4342 raft_consensus.cc:697] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 1 LEADER]: Becoming Leader. State: Replica: 8d50af6462af44e09ee22127420737d5, State: Running, Role: LEADER
I20260812 06:20:02.449468  4327 heartbeater.cc:499] Master 127.3.216.126:45429 was elected leader, sending a full tablet report...
I20260812 06:20:02.449949  4342 consensus_queue.cc:237] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [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: "8d50af6462af44e09ee22127420737d5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 33371 } }
I20260812 06:20:02.451520  4182 catalog_manager.cc:5719] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8d50af6462af44e09ee22127420737d5 (127.3.216.65). New cstate: current_term: 1 leader_uuid: "8d50af6462af44e09ee22127420737d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8d50af6462af44e09ee22127420737d5" member_type: VOTER last_known_addr { host: "127.3.216.65" port: 33371 } health_report { overall_health: HEALTHY } } }
I20260812 06:20:02.511245  3937 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.015s	sys 0.008s
I20260812 06:20:02.660041  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=19.054940
I20260812 06:20:02.826223  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.166s	user 0.109s	sys 0.055s Metrics: {"bytes_written":12307489,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":89,"dirs.run_cpu_time_us":195,"dirs.run_wall_time_us":857,"drs_written":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4,"lbm_write_time_us":43019,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"update_count":1500}
I20260812 06:20:02.826967  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): free 20743880 bytes of WAL
I20260812 06:20:02.827212  4261 log_reader.cc:385] T 1f89eebd03dd4d1d94efa6b50cd34f7d: removed 2 log segments from log reader
I20260812 06:20:02.827255  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000001 (ops 1-6)
I20260812 06:20:02.827286  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000002 (ops 7-11)
I20260812 06:20:02.831718  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:20:02.832115  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): 16411394 bytes on disk
I20260812 06:20:02.832628  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:02.833031  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:02.849784  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5795,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:02.850239  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:03.018035  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.168s	user 0.113s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672275,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":874,"lbm_read_time_us":11178,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24681,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1536,"thread_start_us":380,"threads_started":5,"update_count":2000}
I20260812 06:20:03.018728  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:03.080029  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.061s	user 0.034s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18810,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.080631  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:03.091657  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4448,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.092106  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:03.299324  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.207s	user 0.131s	sys 0.064s 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":1004,"lbm_read_time_us":13231,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33036,"lbm_writes_lt_1ms":543,"mutex_wait_us":319,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11264,"update_count":2500}
I20260812 06:20:03.300781  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:03.358444  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.057s	user 0.041s	sys 0.014s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25266,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.358951  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:03.381644  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.022s	user 0.000s	sys 0.021s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5181,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.382334  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:03.575675  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.193s	user 0.137s	sys 0.054s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":382,"lbm_read_time_us":12780,"lbm_reads_lt_1ms":564,"lbm_write_time_us":31073,"lbm_writes_lt_1ms":543,"mutex_wait_us":39,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:20:03.576341  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:03.627326  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.051s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409911,"delete_count":0,"lbm_write_time_us":23020,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.627951  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:03.645004  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6731,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.645481  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:03.840916  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.195s	user 0.110s	sys 0.074s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774698,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":767,"lbm_read_time_us":11760,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31610,"lbm_writes_lt_1ms":543,"mutex_wait_us":60,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2500}
I20260812 06:20:03.841660  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:03.890120  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.048s	user 0.036s	sys 0.009s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20242,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:03.890676  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:03.903648  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4804,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:03.904304  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:04.061189  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.157s	user 0.104s	sys 0.047s 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":61,"lbm_read_time_us":9905,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31145,"lbm_writes_lt_1ms":543,"mutex_wait_us":47,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.062116  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=11.118625
I20260812 06:20:04.096936  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.035s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":15025,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:04.097518  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:04.111598  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4956,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.112092  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:04.151724  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.039s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":282,"dirs.run_wall_time_us":1415,"drs_written":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1527,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:20:04.152508  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=3.181125
I20260812 06:20:04.165397  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4454,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:20:04.165931  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): free 115943176 bytes of WAL
I20260812 06:20:04.166254  4261 log_reader.cc:385] T 1f89eebd03dd4d1d94efa6b50cd34f7d: removed 11 log segments from log reader
I20260812 06:20:04.166317  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000003 (ops 12-16)
I20260812 06:20:04.166357  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000004 (ops 17-21)
I20260812 06:20:04.166388  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000005 (ops 22-26)
I20260812 06:20:04.166409  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000006 (ops 27-31)
I20260812 06:20:04.166435  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000007 (ops 32-36)
I20260812 06:20:04.166468  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000008 (ops 37-41)
I20260812 06:20:04.166496  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000009 (ops 42-46)
I20260812 06:20:04.166518  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000010 (ops 47-51)
I20260812 06:20:04.166546  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000011 (ops 52-56)
I20260812 06:20:04.166569  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000012 (ops 57-61)
I20260812 06:20:04.166592  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000013 (ops 62-66)
I20260812 06:20:04.196925  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.031s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:04.197510  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): 462 bytes on disk
I20260812 06:20:04.198038  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":83,"lbm_reads_lt_1ms":4}
I20260812 06:20:04.198642  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:04.234108  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.035s	user 0.011s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4838,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:04.234783  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:04.245913  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4229,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.246382  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:04.502780  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.256s	user 0.172s	sys 0.075s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":32979852,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":670,"lbm_read_time_us":15427,"lbm_reads_lt_1ms":775,"lbm_write_time_us":40662,"lbm_writes_lt_1ms":743,"mutex_wait_us":259,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":17152,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:20:04.503328  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=18.063937
I20260812 06:20:04.580653  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.077s	user 0.043s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":30085,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.581173  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:04.592486  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4037,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.592988  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:04.805491  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.212s	user 0.114s	sys 0.087s 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":216,"lbm_read_time_us":15770,"lbm_reads_lt_1ms":672,"lbm_write_time_us":32869,"lbm_writes_lt_1ms":643,"mutex_wait_us":61,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":32384,"update_count":3000}
I20260812 06:20:04.806227  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=18.063937
I20260812 06:20:04.879696  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.073s	user 0.038s	sys 0.024s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":29701,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:20:04.880267  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:04.892262  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4176,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:04.892795  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.105405  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.212s	user 0.148s	sys 0.064s 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":342,"lbm_read_time_us":16091,"lbm_reads_lt_1ms":672,"lbm_write_time_us":35864,"lbm_writes_lt_1ms":643,"mutex_wait_us":46,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6784,"update_count":3000}
I20260812 06:20:05.106163  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:05.170248  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.064s	user 0.038s	sys 0.012s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23133,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:05.170786  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:05.183311  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4313,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.183952  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.361940  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.178s	user 0.106s	sys 0.067s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":12493,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29248,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":2500}
I20260812 06:20:05.362574  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=11.118625
I20260812 06:20:05.414201  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.051s	user 0.027s	sys 0.023s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15607,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:20:05.415027  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:05.425913  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.010s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:20:05.426594  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.576728  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.150s	user 0.104s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":402,"lbm_read_time_us":11163,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23515,"lbm_writes_lt_1ms":443,"mutex_wait_us":54,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:20:05.577517  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=10.126437
I20260812 06:20:05.623405  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.046s	user 0.017s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17664,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.623975  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:05.635128  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.635852  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.763535  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.127s	user 0.098s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":341,"lbm_read_time_us":8047,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26177,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11008,"update_count":2000}
I20260812 06:20:05.764202  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=10.126437
I20260812 06:20:05.811720  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.047s	user 0.028s	sys 0.008s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17269,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:20:05.812305  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:05.823734  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:05.824676  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.856235  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.031s	user 0.029s	sys 0.001s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":244,"dirs.run_wall_time_us":1612,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1637,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:05.857007  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): free 129773563 bytes of WAL
I20260812 06:20:05.857254  4261 log_reader.cc:385] T 1f89eebd03dd4d1d94efa6b50cd34f7d: removed 13 log segments from log reader
I20260812 06:20:05.857323  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000014 (ops 67-71)
I20260812 06:20:05.857384  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000015 (ops 72-76)
I20260812 06:20:05.857429  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000016 (ops 77-81)
I20260812 06:20:05.857473  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000017 (ops 82-86)
I20260812 06:20:05.857517  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000018 (ops 87-91)
I20260812 06:20:05.857555  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000019 (ops 92-96)
I20260812 06:20:05.857592  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000020 (ops 97-100)
I20260812 06:20:05.857676  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000021 (ops 101-105)
I20260812 06:20:05.857719  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000022 (ops 106-110)
I20260812 06:20:05.857755  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000023 (ops 111-115)
I20260812 06:20:05.857792  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000024 (ops 116-120)
I20260812 06:20:05.857829  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000025 (ops 121-125)
I20260812 06:20:05.857865  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000026 (ops 126-130)
I20260812 06:20:05.886899  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.030s	user 0.000s	sys 0.027s Metrics: {}
I20260812 06:20:05.887327  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): 483 bytes on disk
I20260812 06:20:05.887845  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:20:05.888350  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=4.173312
I20260812 06:20:05.908349  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.020s	user 0.014s	sys 0.003s Metrics: {"bytes_written":6194894,"delete_count":0,"lbm_write_time_us":8540,"lbm_writes_lt_1ms":154,"reinsert_count":0,"update_count":755}
I20260812 06:20:05.908861  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:05.920997  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":2010377,"delete_count":0,"lbm_write_time_us":3424,"lbm_writes_lt_1ms":52,"reinsert_count":0,"update_count":245}
I20260812 06:20:05.921563  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:06.096187  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.174s	user 0.134s	sys 0.040s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877289,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1264,"lbm_read_time_us":12986,"lbm_reads_lt_1ms":666,"lbm_write_time_us":34485,"lbm_writes_lt_1ms":643,"mutex_wait_us":312,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22144,"thread_start_us":102,"threads_started":1,"update_count":3000}
I20260812 06:20:06.096993  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:06.144424  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.047s	user 0.025s	sys 0.017s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20242,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.145217  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:06.157312  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.012s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4309,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.158221  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:06.319327  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.161s	user 0.115s	sys 0.045s 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":228,"lbm_read_time_us":12678,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28745,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"update_count":2500}
I20260812 06:20:06.320101  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=12.110812
I20260812 06:20:06.360029  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.040s	user 0.016s	sys 0.020s Metrics: {"bytes_written":13743339,"delete_count":0,"lbm_write_time_us":17800,"lbm_writes_lt_1ms":338,"reinsert_count":0,"update_count":1675}
I20260812 06:20:06.360531  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.196750
I20260812 06:20:06.374363  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.014s	user 0.005s	sys 0.005s Metrics: {"bytes_written":2666779,"delete_count":0,"lbm_write_time_us":4082,"lbm_writes_lt_1ms":68,"reinsert_count":0,"update_count":325}
I20260812 06:20:06.375036  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:06.543517  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.168s	user 0.117s	sys 0.043s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672246,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":366,"lbm_read_time_us":11440,"lbm_reads_lt_1ms":464,"lbm_write_time_us":25458,"lbm_writes_lt_1ms":443,"mutex_wait_us":59,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":2000}
I20260812 06:20:06.544368  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:06.593257  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.049s	user 0.020s	sys 0.028s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":21442,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.593711  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:06.615105  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.021s	user 0.011s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.615729  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:06.803049  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.187s	user 0.134s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774690,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1071,"lbm_read_time_us":12422,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31161,"lbm_writes_lt_1ms":543,"mutex_wait_us":291,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15744,"update_count":2500}
I20260812 06:20:06.803654  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:06.854866  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.051s	user 0.017s	sys 0.031s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":24031,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:20:06.855458  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:06.868729  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.013s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4643,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:06.869392  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:07.042344  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.173s	user 0.125s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":879,"lbm_read_time_us":9990,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28517,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":34560,"update_count":2500}
I20260812 06:20:07.043138  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=10.126437
I20260812 06:20:07.088328  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.045s	user 0.025s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":22034,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":300,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.089231  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:07.115548  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.026s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5736,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.116029  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:07.127722  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.128360  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:07.307855  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.179s	user 0.137s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":174,"lbm_read_time_us":10986,"lbm_reads_lt_1ms":573,"lbm_write_time_us":31829,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:20:07.308676  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=14.095187
I20260812 06:20:07.363411  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.055s	user 0.027s	sys 0.021s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22689,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:20:07.363914  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:07.375735  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:20:07.376466  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:07.405642  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushMRSOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.029s	user 0.023s	sys 0.005s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":73,"dirs.run_cpu_time_us":181,"dirs.run_wall_time_us":1202,"drs_written":1,"lbm_read_time_us":44,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1946,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:20:07.406461  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): free 127961386 bytes of WAL
I20260812 06:20:07.406742  4261 log_reader.cc:385] T 1f89eebd03dd4d1d94efa6b50cd34f7d: removed 12 log segments from log reader
I20260812 06:20:07.406816  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000027 (ops 131-135)
I20260812 06:20:07.406893  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000028 (ops 136-140)
I20260812 06:20:07.406932  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000029 (ops 141-145)
I20260812 06:20:07.406966  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000030 (ops 146-150)
I20260812 06:20:07.407001  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000031 (ops 151-155)
I20260812 06:20:07.407040  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000032 (ops 156-160)
I20260812 06:20:07.407083  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000033 (ops 161-165)
I20260812 06:20:07.407124  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000034 (ops 166-170)
I20260812 06:20:07.407161  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000035 (ops 171-175)
I20260812 06:20:07.407207  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000036 (ops 176-180)
I20260812 06:20:07.407243  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000037 (ops 181-185)
I20260812 06:20:07.407284  4261 log.cc:1079] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: Deleting log segment in path: /tmp/dist-test-taskivavOS/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515596531926-3937-0/minicluster-data/ts-0-root/wals/1f89eebd03dd4d1d94efa6b50cd34f7d/wal-000000038 (ops 186-190)
I20260812 06:20:07.439935  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: LogGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.033s	user 0.000s	sys 0.030s Metrics: {}
I20260812 06:20:07.440522  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d): 482 bytes on disk
I20260812 06:20:07.441073  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: UndoDeltaBlockGCOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4}
I20260812 06:20:07.441659  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=3.181125
I20260812 06:20:07.454396  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4553930,"delete_count":0,"lbm_write_time_us":5217,"lbm_writes_lt_1ms":114,"reinsert_count":0,"update_count":555}
I20260812 06:20:07.454854  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=2.188937
I20260812 06:20:07.477392  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.022s	user 0.002s	sys 0.019s Metrics: {"bytes_written":3651380,"delete_count":0,"lbm_write_time_us":3847,"lbm_writes_lt_1ms":92,"reinsert_count":0,"update_count":445}
I20260812 06:20:07.478040  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=1.000000
I20260812 06:20:07.611475  3937 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.100s	user 1.935s	sys 0.150s
I20260812 06:20:07.694694  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: MajorDeltaCompactionOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.216s	user 0.148s	sys 0.069s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979742,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":354,"lbm_read_time_us":17412,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35474,"lbm_writes_lt_1ms":743,"mutex_wait_us":39,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":35968,"thread_start_us":86,"threads_started":1,"update_count":3500}
I20260812 06:20:07.695389  4328 maintenance_manager.cc:419] P 8d50af6462af44e09ee22127420737d5: Scheduling FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d): perf score=10.126437
I20260812 06:20:07.703395  3937 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.092s	user 0.000s	sys 0.001s
I20260812 06:20:07.703896  3937 tablet_server.cc:179] TabletServer@127.3.216.65:0 shutting down...
I20260812 06:20:07.728889  4261 maintenance_manager.cc:643] P 8d50af6462af44e09ee22127420737d5: FlushDeltaMemStoresOp(1f89eebd03dd4d1d94efa6b50cd34f7d) complete. Timing: real 0.033s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14230,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:20:07.729558  3937 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:20:07.729769  3937 tablet_replica.cc:333] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5: stopping tablet replica
I20260812 06:20:07.729933  3937 raft_consensus.cc:2243] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.730109  3937 raft_consensus.cc:2272] T 1f89eebd03dd4d1d94efa6b50cd34f7d P 8d50af6462af44e09ee22127420737d5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.734041  3937 tablet_server.cc:196] TabletServer@127.3.216.65:0 shutdown complete.
I20260812 06:20:07.753928  3937 master.cc:562] Master@127.3.216.126:45429 shutting down...
I20260812 06:20:07.757469  3937 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:20:07.757696  3937 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:20:07.757803  3937 tablet_replica.cc:333] T 00000000000000000000000000000000 P 3f236870c955462b854ae3f5a45d1cff: stopping tablet replica
I20260812 06:20:07.770383  3937 master.cc:584] Master@127.3.216.126:45429 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5567 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11319 ms total)

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