[==========] 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:02.679140  5302 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.45.190:38275
I20260812 06:19:02.680190  5302 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:02.680816  5302 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.687804  5310 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:02.687814  5313 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:02.687876  5302 server_base.cc:1061] running on GCE node
W20260812 06:19:02.688086  5309 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:02.688644  5302 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.688786  5302 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:02.688848  5302 hybrid_clock.cc:648] HybridClock initialized: now 1786515542688846 us; error 0 us; skew 500 ppm
I20260812 06:19:02.690574  5302 webserver.cc:533] Webserver started at http://127.5.45.190:45541/ using document root <none> and password file <none>
I20260812 06:19:02.691154  5302 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.691224  5302 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.691429  5302 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.693068  5302 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/master-0-root/instance:
uuid: "8141e51613d6430cb8675ced0c5782e5"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-n326"
I20260812 06:19:02.696640  5302 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:19:02.698669  5321 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:02.699730  5302 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.699827  5302 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/master-0-root
uuid: "8141e51613d6430cb8675ced0c5782e5"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-n326"
I20260812 06:19:02.699962  5302 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-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:02.720274  5302 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.720999  5302 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:02.721197  5302 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.729199  5302 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.190:38275
I20260812 06:19:02.729210  5414 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.190:38275 every 8 connection(s)
I20260812 06:19:02.731642  5415 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:02.737540  5415 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: Bootstrap starting.
I20260812 06:19:02.740185  5415 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.741197  5415 log.cc:826] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:02.743093  5415 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: No bootstrap required, opened a new log
I20260812 06:19:02.746179  5415 raft_consensus.cc:359] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER }
I20260812 06:19:02.746400  5415 raft_consensus.cc:385] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.746510  5415 raft_consensus.cc:740] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8141e51613d6430cb8675ced0c5782e5, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.747314  5415 consensus_queue.cc:260] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [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: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER }
I20260812 06:19:02.747529  5415 raft_consensus.cc:399] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.747623  5415 raft_consensus.cc:493] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.747797  5415 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.748735  5415 raft_consensus.cc:515] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER }
I20260812 06:19:02.749236  5415 leader_election.cc:304] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [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: 8141e51613d6430cb8675ced0c5782e5; no voters: 
I20260812 06:19:02.749610  5415 leader_election.cc:290] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.749886  5421 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.750180  5421 raft_consensus.cc:697] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 1 LEADER]: Becoming Leader. State: Replica: 8141e51613d6430cb8675ced0c5782e5, State: Running, Role: LEADER
I20260812 06:19:02.750612  5421 consensus_queue.cc:237] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [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: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER }
I20260812 06:19:02.750815  5415 sys_catalog.cc:565] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.752939  5429 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 8141e51613d6430cb8675ced0c5782e5. Latest consensus state: current_term: 1 leader_uuid: "8141e51613d6430cb8675ced0c5782e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER } }
I20260812 06:19:02.753016  5426 sys_catalog.cc:455] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "8141e51613d6430cb8675ced0c5782e5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8141e51613d6430cb8675ced0c5782e5" member_type: VOTER } }
I20260812 06:19:02.753085  5429 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.753118  5426 sys_catalog.cc:458] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.753580  5302 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.753540  5452 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.756486  5452 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.761945  5452 catalog_manager.cc:1383] Generated new cluster ID: 9084fdb27c0647cd890226679876b750
I20260812 06:19:02.762053  5452 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.783020  5452 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.783978  5452 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.797716  5452 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: Generated new TSK 0
I20260812 06:19:02.798426  5452 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.818626  5302 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.821779  5462 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:02.821781  5461 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:02.821826  5467 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:02.822208  5302 server_base.cc:1061] running on GCE node
I20260812 06:19:02.822386  5302 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.822435  5302 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:02.822459  5302 hybrid_clock.cc:648] HybridClock initialized: now 1786515542822458 us; error 0 us; skew 500 ppm
I20260812 06:19:02.823455  5302 webserver.cc:533] Webserver started at http://127.5.45.129:39861/ using document root <none> and password file <none>
I20260812 06:19:02.823629  5302 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.823688  5302 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.823756  5302 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.824213  5302 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/instance:
uuid: "1b368d07ecde4e42a65b1e526774eee3"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-n326"
I20260812 06:19:02.826050  5302 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:02.827224  5478 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:02.827557  5302 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:02.827628  5302 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root
uuid: "1b368d07ecde4e42a65b1e526774eee3"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-n326"
I20260812 06:19:02.827724  5302 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-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:02.841483  5302 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.842018  5302 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.842561  5302 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.843556  5302 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.843614  5302 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.843690  5302 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.843737  5302 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.851506  5302 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.129:43123
I20260812 06:19:02.851547  5587 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.129:43123 every 8 connection(s)
I20260812 06:19:02.862704  5588 heartbeater.cc:344] Connected to a master server at 127.5.45.190:38275
I20260812 06:19:02.862946  5588 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.863394  5588 heartbeater.cc:507] Master 127.5.45.190:38275 requested a full tablet report, sending...
I20260812 06:19:02.864811  5348 ts_manager.cc:194] Registered new tserver with Master: 1b368d07ecde4e42a65b1e526774eee3 (127.5.45.129:43123)
I20260812 06:19:02.865764  5302 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.013440729s
I20260812 06:19:02.865949  5348 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58576
I20260812 06:19:02.875919  5348 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58578:
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:02.891709  5521 tablet_service.cc:1511] Processing CreateTablet for tablet e4b3dbd0ecb74b3f8c49c478b902d431 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8c90f76cfe6b4791beab6b59b11ea701]), partition=
I20260812 06:19:02.892195  5521 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet e4b3dbd0ecb74b3f8c49c478b902d431. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.895318  5612 tablet_bootstrap.cc:492] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Bootstrap starting.
I20260812 06:19:02.896277  5612 tablet_bootstrap.cc:654] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.897547  5612 tablet_bootstrap.cc:492] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: No bootstrap required, opened a new log
I20260812 06:19:02.897687  5612 ts_tablet_manager.cc:1403] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.898483  5612 raft_consensus.cc:359] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b368d07ecde4e42a65b1e526774eee3" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 43123 } }
I20260812 06:19:02.898681  5612 raft_consensus.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.898775  5612 raft_consensus.cc:740] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 1b368d07ecde4e42a65b1e526774eee3, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.898960  5612 consensus_queue.cc:260] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [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: "1b368d07ecde4e42a65b1e526774eee3" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 43123 } }
I20260812 06:19:02.899139  5612 raft_consensus.cc:399] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.899262  5612 raft_consensus.cc:493] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.899354  5612 raft_consensus.cc:3060] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.900192  5612 raft_consensus.cc:515] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b368d07ecde4e42a65b1e526774eee3" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 43123 } }
I20260812 06:19:02.900364  5612 leader_election.cc:304] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [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: 1b368d07ecde4e42a65b1e526774eee3; no voters: 
I20260812 06:19:02.900642  5612 leader_election.cc:290] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.900751  5614 raft_consensus.cc:2804] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.900985  5614 raft_consensus.cc:697] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 1 LEADER]: Becoming Leader. State: Replica: 1b368d07ecde4e42a65b1e526774eee3, State: Running, Role: LEADER
I20260812 06:19:02.901083  5612 ts_tablet_manager.cc:1434] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Time spent starting tablet: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:02.901240  5614 consensus_queue.cc:237] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [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: "1b368d07ecde4e42a65b1e526774eee3" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 43123 } }
I20260812 06:19:02.901415  5588 heartbeater.cc:499] Master 127.5.45.190:38275 was elected leader, sending a full tablet report...
I20260812 06:19:02.904330  5348 catalog_manager.cc:5719] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 reported cstate change: term changed from 0 to 1, leader changed from <none> to 1b368d07ecde4e42a65b1e526774eee3 (127.5.45.129). New cstate: current_term: 1 leader_uuid: "1b368d07ecde4e42a65b1e526774eee3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "1b368d07ecde4e42a65b1e526774eee3" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 43123 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:02.976589  5302 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.064s	user 0.018s	sys 0.012s
I20260812 06:19:03.102861  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=15.086190
I20260812 06:19:03.265442  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.162s	user 0.116s	sys 0.037s Metrics: {"bytes_written":11897249,"cfile_init":1,"compiler_manager_pool.queue_time_us":256,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":938,"drs_written":1,"lbm_read_time_us":82,"lbm_reads_lt_1ms":4,"lbm_write_time_us":38817,"lbm_writes_lt_1ms":657,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"thread_start_us":117,"threads_started":1,"update_count":1450}
I20260812 06:19:03.266691  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): free 20743880 bytes of WAL
I20260812 06:19:03.267006  5484 log_reader.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431: removed 2 log segments from log reader
I20260812 06:19:03.267086  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000001 (ops 1-6)
I20260812 06:19:03.267144  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000002 (ops 7-11)
I20260812 06:19:03.273252  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.006s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:19:03.273682  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): 12719216 bytes on disk
I20260812 06:19:03.274356  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.001s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.274796  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:03.297451  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.022s	user 0.005s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.297993  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:03.426234  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.128s	user 0.092s	sys 0.036s Metrics: {"cfile_cache_miss":422,"cfile_cache_miss_bytes":20262036,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":738,"lbm_read_time_us":9609,"lbm_reads_lt_1ms":450,"lbm_write_time_us":24589,"lbm_writes_lt_1ms":433,"peak_mem_usage":49238594,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":319,"threads_started":5,"update_count":1950}
I20260812 06:19:03.426838  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:03.467927  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.041s	user 0.028s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18241,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.468357  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:03.479288  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4273,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.479948  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:03.605230  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.125s	user 0.091s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":241,"lbm_read_time_us":9736,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24676,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14208,"update_count":2000}
I20260812 06:19:03.605754  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:03.655059  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.049s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18511,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.655607  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:03.666358  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4300,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.666812  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:03.792688  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.126s	user 0.094s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":599,"lbm_read_time_us":10312,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23158,"lbm_writes_lt_1ms":443,"mutex_wait_us":74,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.793475  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:03.837634  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.044s	user 0.026s	sys 0.015s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16195,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:03.838112  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:03.846463  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.008s	user 0.000s	sys 0.003s Metrics: {"bytes_written":1271932,"delete_count":0,"lbm_write_time_us":1308,"lbm_writes_lt_1ms":34,"reinsert_count":0,"update_count":155}
I20260812 06:19:03.846912  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.196750
I20260812 06:19:03.855006  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":2830880,"delete_count":0,"lbm_write_time_us":3049,"lbm_writes_lt_1ms":72,"reinsert_count":0,"update_count":345}
I20260812 06:19:03.855450  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:04.012044  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.156s	user 0.089s	sys 0.060s Metrics: {"cfile_cache_miss":433,"cfile_cache_miss_bytes":20672302,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":369,"lbm_read_time_us":10851,"lbm_reads_lt_1ms":473,"lbm_write_time_us":23241,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11392,"update_count":2000}
I20260812 06:19:04.012580  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:04.052268  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.040s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14264,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.052816  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:04.160477  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.107s	user 0.073s	sys 0.034s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":239,"lbm_read_time_us":7476,"lbm_reads_lt_1ms":363,"lbm_write_time_us":19678,"lbm_writes_lt_1ms":343,"mutex_wait_us":66,"peak_mem_usage":38262756,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.161216  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:04.219266  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.058s	user 0.028s	sys 0.013s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":17913,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.219861  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:04.239310  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.019s	user 0.009s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":8576,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.239909  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:04.386004  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.146s	user 0.116s	sys 0.027s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":184,"lbm_read_time_us":10817,"lbm_reads_lt_1ms":464,"lbm_write_time_us":29636,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20224,"update_count":2000}
I20260812 06:19:04.386518  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:04.444495  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.058s	user 0.030s	sys 0.022s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":19431,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.445067  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:04.456768  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4647,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.457221  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:04.613247  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.156s	user 0.110s	sys 0.045s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":399,"lbm_read_time_us":12065,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26461,"lbm_writes_lt_1ms":443,"mutex_wait_us":109,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.613808  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:04.662339  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.048s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15708,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.662906  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:04.674871  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.012s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4556,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.675436  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:04.709017  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.033s	user 0.027s	sys 0.005s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1341,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1856,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:04.709822  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): free 120553388 bytes of WAL
I20260812 06:19:04.710067  5484 log_reader.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431: removed 12 log segments from log reader
I20260812 06:19:04.710114  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000003 (ops 12-16)
I20260812 06:19:04.710142  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000004 (ops 17-20)
I20260812 06:19:04.710206  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000005 (ops 21-25)
I20260812 06:19:04.710237  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000006 (ops 26-30)
I20260812 06:19:04.710278  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000007 (ops 31-34)
I20260812 06:19:04.710337  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000008 (ops 35-39)
I20260812 06:19:04.710376  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000009 (ops 40-44)
I20260812 06:19:04.710412  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000010 (ops 45-49)
I20260812 06:19:04.710454  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000011 (ops 50-54)
I20260812 06:19:04.710491  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000012 (ops 55-59)
I20260812 06:19:04.710530  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000013 (ops 60-64)
I20260812 06:19:04.710569  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000014 (ops 65-69)
I20260812 06:19:04.740501  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.030s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:04.740989  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=3.181125
I20260812 06:19:04.759497  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.018s	user 0.013s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":7272,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.759953  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): 472 bytes on disk
I20260812 06:19:04.760375  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.760841  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:04.779392  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.018s	user 0.003s	sys 0.015s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3974,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.779911  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:05.004967  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.225s	user 0.137s	sys 0.087s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877326,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":753,"lbm_read_time_us":16092,"lbm_reads_lt_1ms":674,"lbm_write_time_us":39688,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":39680,"thread_start_us":106,"threads_started":1,"update_count":3000}
I20260812 06:19:05.006768  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:05.105938  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.099s	user 0.052s	sys 0.044s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":39239,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.106906  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:05.129009  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.022s	user 0.019s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8673,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.131682  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:05.499315  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.367s	user 0.220s	sys 0.144s 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":581,"lbm_read_time_us":30560,"lbm_reads_lt_1ms":572,"lbm_write_time_us":65151,"lbm_writes_lt_1ms":543,"mutex_wait_us":920,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.500288  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:05.608708  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.108s	user 0.062s	sys 0.043s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":53575,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.609586  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:05.631546  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.022s	user 0.005s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":8966,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.632236  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:05.959555  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.327s	user 0.229s	sys 0.087s 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":244,"lbm_read_time_us":22175,"lbm_reads_lt_1ms":572,"lbm_write_time_us":57913,"lbm_writes_lt_1ms":543,"mutex_wait_us":81,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":15104,"update_count":2500}
I20260812 06:19:05.960723  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=11.118625
I20260812 06:19:06.040001  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.079s	user 0.053s	sys 0.019s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":31962,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.041002  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.065192  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.024s	user 0.014s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.066181  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.086709  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.020s	user 0.017s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":7598,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.087908  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:06.281646  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.193s	user 0.153s	sys 0.039s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774800,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":219,"lbm_read_time_us":22047,"lbm_reads_lt_1ms":573,"lbm_write_time_us":32983,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:06.282276  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=11.118625
I20260812 06:19:06.331218  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.049s	user 0.036s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":20726,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":311,"reinsert_count":0,"update_count":1550}
I20260812 06:19:06.331792  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.351863  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.020s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3938559,"delete_count":0,"lbm_write_time_us":4543,"lbm_writes_lt_1ms":99,"reinsert_count":0,"update_count":480}
I20260812 06:19:06.352438  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.367673  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":3856509,"delete_count":0,"lbm_write_time_us":5892,"lbm_writes_lt_1ms":97,"reinsert_count":0,"update_count":470}
I20260812 06:19:06.368157  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:06.519577  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.151s	user 0.134s	sys 0.016s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774803,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":531,"lbm_read_time_us":12040,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27765,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14336,"update_count":2500}
I20260812 06:19:06.520350  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:06.556533  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.036s	user 0.023s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14472,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.557061  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.571381  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.014s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.573310  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:06.712438  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.139s	user 0.099s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":388,"lbm_read_time_us":9038,"lbm_reads_lt_1ms":468,"lbm_write_time_us":28001,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:06.713114  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=10.126437
I20260812 06:19:06.753674  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.040s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18583,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.754204  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:06.770780  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6341,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.771286  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:06.803458  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":62,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1307,"drs_written":1,"lbm_read_time_us":45,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1594,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:06.804212  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): free 121006446 bytes of WAL
I20260812 06:19:06.804481  5484 log_reader.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431: removed 12 log segments from log reader
I20260812 06:19:06.804523  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000015 (ops 70-74)
I20260812 06:19:06.804554  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000016 (ops 75-79)
I20260812 06:19:06.804625  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000017 (ops 80-84)
I20260812 06:19:06.804653  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000018 (ops 85-88)
I20260812 06:19:06.804693  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000019 (ops 89-93)
I20260812 06:19:06.804733  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000020 (ops 94-98)
I20260812 06:19:06.804771  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000021 (ops 99-103)
I20260812 06:19:06.804811  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000022 (ops 104-108)
I20260812 06:19:06.804849  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000023 (ops 109-113)
I20260812 06:19:06.804898  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000024 (ops 114-118)
I20260812 06:19:06.804934  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000025 (ops 119-123)
I20260812 06:19:06.804972  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000026 (ops 124-128)
I20260812 06:19:06.836249  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.032s	user 0.004s	sys 0.027s Metrics: {}
I20260812 06:19:06.836773  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): 481 bytes on disk
I20260812 06:19:06.837443  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4}
I20260812 06:19:06.838241  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=5.165500
I20260812 06:19:06.858215  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":6358991,"delete_count":0,"lbm_write_time_us":8352,"lbm_writes_lt_1ms":158,"reinsert_count":0,"update_count":775}
I20260812 06:19:06.858701  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): free 12017947 bytes of WAL
I20260812 06:19:06.858945  5484 log_reader.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431: removed 1 log segments from log reader
I20260812 06:19:06.859004  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000027 (ops 129-133)
I20260812 06:19:06.862435  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.004s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:06.862828  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:06.871541  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":1846277,"delete_count":0,"lbm_write_time_us":3012,"lbm_writes_lt_1ms":48,"reinsert_count":0,"update_count":225}
I20260812 06:19:06.872020  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:07.043802  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.171s	user 0.113s	sys 0.056s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877284,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":752,"lbm_read_time_us":11828,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34959,"lbm_writes_lt_1ms":643,"mutex_wait_us":478,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11136,"thread_start_us":83,"threads_started":1,"update_count":3000}
I20260812 06:19:07.044618  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:07.102319  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.057s	user 0.029s	sys 0.024s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":28478,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":400,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.102897  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:07.126345  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.023s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6252,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.126804  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:07.137945  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4339,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.138433  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:07.306680  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.168s	user 0.140s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877219,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":706,"lbm_read_time_us":13194,"lbm_reads_lt_1ms":673,"lbm_write_time_us":36670,"lbm_writes_lt_1ms":643,"mutex_wait_us":331,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":38272,"update_count":3000}
I20260812 06:19:07.307320  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:07.365944  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.058s	user 0.036s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26003,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.366497  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:07.384909  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.018s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5429,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.385496  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:07.544807  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.159s	user 0.112s	sys 0.047s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":176,"lbm_read_time_us":9559,"lbm_reads_lt_1ms":564,"lbm_write_time_us":30118,"lbm_writes_lt_1ms":543,"mutex_wait_us":43,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.545392  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:07.597867  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.052s	user 0.033s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23672,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.598399  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:07.754256  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.156s	user 0.105s	sys 0.043s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":682,"lbm_read_time_us":10515,"lbm_reads_lt_1ms":463,"lbm_write_time_us":25745,"lbm_writes_lt_1ms":443,"mutex_wait_us":20,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8960,"update_count":2000}
I20260812 06:19:07.755095  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:07.809185  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.054s	user 0.024s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21118,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.809722  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:07.821797  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4511,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.822317  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:08.014814  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.192s	user 0.132s	sys 0.056s 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":507,"lbm_read_time_us":12218,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33498,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17664,"update_count":2500}
I20260812 06:19:08.015420  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=14.095187
I20260812 06:19:08.072031  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.056s	user 0.029s	sys 0.023s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":24234,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.072573  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:08.088506  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.016s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6124,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.089321  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:08.242259  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.153s	user 0.110s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":891,"lbm_read_time_us":11078,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29049,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:08.242909  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=11.118625
I20260812 06:19:08.278393  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.035s	user 0.021s	sys 0.011s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15616,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.278991  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:08.294142  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5414,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.294665  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:08.349241  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushMRSOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.054s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":166,"dirs.run_wall_time_us":1273,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1701,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:08.349993  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): free 121006705 bytes of WAL
I20260812 06:19:08.350231  5484 log_reader.cc:385] T e4b3dbd0ecb74b3f8c49c478b902d431: removed 12 log segments from log reader
I20260812 06:19:08.350301  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000028 (ops 134-138)
I20260812 06:19:08.350361  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000029 (ops 139-143)
I20260812 06:19:08.350430  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000030 (ops 144-148)
I20260812 06:19:08.350481  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000031 (ops 149-153)
I20260812 06:19:08.350521  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000032 (ops 154-158)
I20260812 06:19:08.350565  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000033 (ops 159-163)
I20260812 06:19:08.350608  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000034 (ops 164-168)
I20260812 06:19:08.350652  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000035 (ops 169-172)
I20260812 06:19:08.350695  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000036 (ops 173-177)
I20260812 06:19:08.350739  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000037 (ops 178-182)
I20260812 06:19:08.350781  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000038 (ops 183-187)
I20260812 06:19:08.350824  5484 log.cc:1079] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/e4b3dbd0ecb74b3f8c49c478b902d431/wal-000000039 (ops 188-192)
I20260812 06:19:08.382938  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: LogGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.033s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:08.383463  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431): 483 bytes on disk
I20260812 06:19:08.384073  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: UndoDeltaBlockGCOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.384733  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=7.149875
I20260812 06:19:08.424964  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.040s	user 0.017s	sys 0.021s Metrics: {"bytes_written":8779420,"delete_count":0,"lbm_write_time_us":12599,"lbm_writes_lt_1ms":217,"reinsert_count":0,"update_count":1070}
I20260812 06:19:08.425655  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=2.188937
I20260812 06:19:08.440130  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: FlushDeltaMemStoresOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.014s	user 0.012s	sys 0.001s Metrics: {"bytes_written":3528305,"delete_count":0,"lbm_write_time_us":5329,"lbm_writes_lt_1ms":89,"reinsert_count":0,"update_count":430}
I20260812 06:19:08.440675  5589 maintenance_manager.cc:419] P 1b368d07ecde4e42a65b1e526774eee3: Scheduling MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431): perf score=1.000000
I20260812 06:19:08.527817  5302 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.551s	user 2.067s	sys 0.124s
I20260812 06:19:08.640282  5302 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.112s	user 0.003s	sys 0.000s
I20260812 06:19:08.640959  5302 tablet_server.cc:179] TabletServer@127.5.45.129:0 shutting down...
I20260812 06:19:08.649318  5484 maintenance_manager.cc:643] P 1b368d07ecde4e42a65b1e526774eee3: MajorDeltaCompactionOp(e4b3dbd0ecb74b3f8c49c478b902d431) complete. Timing: real 0.208s	user 0.130s	sys 0.077s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979731,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1156,"lbm_read_time_us":16181,"lbm_reads_lt_1ms":766,"lbm_write_time_us":33397,"lbm_writes_lt_1ms":743,"mutex_wait_us":20,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":5376,"thread_start_us":78,"threads_started":1,"update_count":3500}
I20260812 06:19:08.652225  5302 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:08.652794  5302 tablet_replica.cc:333] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3: stopping tablet replica
I20260812 06:19:08.653100  5302 raft_consensus.cc:2243] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.653431  5302 raft_consensus.cc:2272] T e4b3dbd0ecb74b3f8c49c478b902d431 P 1b368d07ecde4e42a65b1e526774eee3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.670023  5302 tablet_server.cc:196] TabletServer@127.5.45.129:0 shutdown complete.
I20260812 06:19:08.706992  5302 master.cc:562] Master@127.5.45.190:38275 shutting down...
I20260812 06:19:08.711490  5302 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.711735  5302 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.711835  5302 tablet_replica.cc:333] T 00000000000000000000000000000000 P 8141e51613d6430cb8675ced0c5782e5: stopping tablet replica
I20260812 06:19:08.724529  5302 master.cc:584] Master@127.5.45.190:38275 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (6138 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:08.832072  5302 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.5.45.190:36213
I20260812 06:19:08.832521  5302 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:08.834707  5648 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:08.834656  5646 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:08.834697  5655 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:08.834815  5302 server_base.cc:1061] running on GCE node
I20260812 06:19:08.835132  5302 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.835186  5302 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:08.835230  5302 hybrid_clock.cc:648] HybridClock initialized: now 1786515548835229 us; error 0 us; skew 500 ppm
I20260812 06:19:08.836117  5302 webserver.cc:533] Webserver started at http://127.5.45.190:45487/ using document root <none> and password file <none>
I20260812 06:19:08.836310  5302 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.836393  5302 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.836475  5302 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.836872  5302 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/master-0-root/instance:
uuid: "367cd7e0f74c49c7beb04d86bbae7f68"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-n326"
I20260812 06:19:08.838399  5302 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:08.839507  5662 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:08.839810  5302 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:08.839913  5302 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/master-0-root
uuid: "367cd7e0f74c49c7beb04d86bbae7f68"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-n326"
I20260812 06:19:08.840011  5302 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-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:08.859653  5302 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.860093  5302 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.864743  5302 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.190:36213
I20260812 06:19:08.870997  5763 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:08.871493  5762 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.190:36213 every 8 connection(s)
I20260812 06:19:08.873029  5763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68: Bootstrap starting.
I20260812 06:19:08.873831  5763 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.874886  5763 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68: No bootstrap required, opened a new log
I20260812 06:19:08.875324  5763 raft_consensus.cc:359] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER }
I20260812 06:19:08.875419  5763 raft_consensus.cc:385] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.875483  5763 raft_consensus.cc:740] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 367cd7e0f74c49c7beb04d86bbae7f68, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.875664  5763 consensus_queue.cc:260] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [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: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER }
I20260812 06:19:08.875737  5763 raft_consensus.cc:399] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.875793  5763 raft_consensus.cc:493] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.875859  5763 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.876538  5763 raft_consensus.cc:515] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER }
I20260812 06:19:08.876677  5763 leader_election.cc:304] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [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: 367cd7e0f74c49c7beb04d86bbae7f68; no voters: 
I20260812 06:19:08.876888  5763 leader_election.cc:290] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.877031  5768 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.877249  5768 raft_consensus.cc:697] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 1 LEADER]: Becoming Leader. State: Replica: 367cd7e0f74c49c7beb04d86bbae7f68, State: Running, Role: LEADER
I20260812 06:19:08.877368  5763 sys_catalog.cc:565] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:08.877399  5768 consensus_queue.cc:237] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [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: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER }
I20260812 06:19:08.877882  5770 sys_catalog.cc:455] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER } }
I20260812 06:19:08.877918  5772 sys_catalog.cc:455] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 367cd7e0f74c49c7beb04d86bbae7f68. Latest consensus state: current_term: 1 leader_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "367cd7e0f74c49c7beb04d86bbae7f68" member_type: VOTER } }
I20260812 06:19:08.877981  5770 sys_catalog.cc:458] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.878003  5772 sys_catalog.cc:458] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.878545  5776 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:08.879560  5776 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:08.879736  5302 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:08.881521  5776 catalog_manager.cc:1383] Generated new cluster ID: 5ca31c98641b46aa8f1e624c50ef6384
I20260812 06:19:08.881579  5776 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:08.889521  5776 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:08.890118  5776 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:08.897951  5776 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68: Generated new TSK 0
I20260812 06:19:08.898155  5776 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:08.912245  5302 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:08.914358  5794 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:08.914398  5793 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:08.914462  5302 server_base.cc:1061] running on GCE node
W20260812 06:19:08.914593  5797 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:08.914824  5302 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.914868  5302 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:08.914884  5302 hybrid_clock.cc:648] HybridClock initialized: now 1786515548914884 us; error 0 us; skew 500 ppm
I20260812 06:19:08.915771  5302 webserver.cc:533] Webserver started at http://127.5.45.129:33499/ using document root <none> and password file <none>
I20260812 06:19:08.915911  5302 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.915958  5302 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.916013  5302 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.916360  5302 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/instance:
uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-n326"
I20260812 06:19:08.917840  5302 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:08.918689  5806 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:08.918936  5302 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:08.919030  5302 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root
uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-n326"
I20260812 06:19:08.919122  5302 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-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:08.952445  5302 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.952893  5302 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.953243  5302 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:08.953752  5302 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:08.953819  5302 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.953876  5302 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:08.953925  5302 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.958463  5302 rpc_server.cc:307] RPC server started. Bound to: 127.5.45.129:39015
I20260812 06:19:08.959720  5938 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.5.45.129:39015 every 8 connection(s)
I20260812 06:19:08.968220  5939 heartbeater.cc:344] Connected to a master server at 127.5.45.190:36213
I20260812 06:19:08.968365  5939 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:08.968665  5939 heartbeater.cc:507] Master 127.5.45.190:36213 requested a full tablet report, sending...
I20260812 06:19:08.969399  5698 ts_manager.cc:194] Registered new tserver with Master: 0f3eb4dbb77c4b91bfff0d42e6ef1925 (127.5.45.129:39015)
I20260812 06:19:08.969470  5302 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010215009s
I20260812 06:19:08.970253  5698 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:54898
I20260812 06:19:08.976998  5698 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:54908:
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:08.986179  5874 tablet_service.cc:1511] Processing CreateTablet for tablet 2632e2f2e0f64e16a06853002162077e (DEFAULT_TABLE table=heavy-update-compaction-test [id=6487c548660c4fde99d591f28569fcdc]), partition=
I20260812 06:19:08.986485  5874 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 2632e2f2e0f64e16a06853002162077e. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:08.988579  5959 tablet_bootstrap.cc:492] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Bootstrap starting.
I20260812 06:19:08.989490  5959 tablet_bootstrap.cc:654] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.990644  5959 tablet_bootstrap.cc:492] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: No bootstrap required, opened a new log
I20260812 06:19:08.990720  5959 ts_tablet_manager.cc:1403] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:08.991230  5959 raft_consensus.cc:359] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 39015 } }
I20260812 06:19:08.991319  5959 raft_consensus.cc:385] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.991341  5959 raft_consensus.cc:740] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0f3eb4dbb77c4b91bfff0d42e6ef1925, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.991590  5959 consensus_queue.cc:260] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [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: "0f3eb4dbb77c4b91bfff0d42e6ef1925" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 39015 } }
I20260812 06:19:08.991709  5959 raft_consensus.cc:399] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.991773  5959 raft_consensus.cc:493] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.991829  5959 raft_consensus.cc:3060] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.992583  5959 raft_consensus.cc:515] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 39015 } }
I20260812 06:19:08.992756  5959 leader_election.cc:304] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [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: 0f3eb4dbb77c4b91bfff0d42e6ef1925; no voters: 
I20260812 06:19:08.992982  5959 leader_election.cc:290] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.993113  5962 raft_consensus.cc:2804] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.993333  5959 ts_tablet_manager.cc:1434] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:08.993402  5939 heartbeater.cc:499] Master 127.5.45.190:36213 was elected leader, sending a full tablet report...
I20260812 06:19:08.993443  5962 raft_consensus.cc:697] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 1 LEADER]: Becoming Leader. State: Replica: 0f3eb4dbb77c4b91bfff0d42e6ef1925, State: Running, Role: LEADER
I20260812 06:19:08.993605  5962 consensus_queue.cc:237] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [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: "0f3eb4dbb77c4b91bfff0d42e6ef1925" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 39015 } }
I20260812 06:19:08.994900  5698 catalog_manager.cc:5719] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 reported cstate change: term changed from 0 to 1, leader changed from <none> to 0f3eb4dbb77c4b91bfff0d42e6ef1925 (127.5.45.129). New cstate: current_term: 1 leader_uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0f3eb4dbb77c4b91bfff0d42e6ef1925" member_type: VOTER last_known_addr { host: "127.5.45.129" port: 39015 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:09.055743  5302 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.011s	sys 0.012s
I20260812 06:19:09.210250  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushMRSOp(2632e2f2e0f64e16a06853002162077e): perf score=19.054940
I20260812 06:19:09.390228  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushMRSOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.180s	user 0.117s	sys 0.059s Metrics: {"bytes_written":12512611,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":206,"dirs.run_wall_time_us":835,"drs_written":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45254,"lbm_writes_lt_1ms":762,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":22528,"update_count":1525}
I20260812 06:19:09.391251  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling LogGCOp(2632e2f2e0f64e16a06853002162077e): free 20743880 bytes of WAL
I20260812 06:19:09.391592  5824 log_reader.cc:385] T 2632e2f2e0f64e16a06853002162077e: removed 2 log segments from log reader
I20260812 06:19:09.391654  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000001 (ops 1-6)
I20260812 06:19:09.391698  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000002 (ops 7-11)
I20260812 06:19:09.398085  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: LogGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.007s	user 0.000s	sys 0.004s Metrics: {}
I20260812 06:19:09.398667  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e): 16411395 bytes on disk
I20260812 06:19:09.399284  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":84,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.399722  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:09.420759  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.021s	user 0.013s	sys 0.003s Metrics: {"bytes_written":3897534,"delete_count":0,"lbm_write_time_us":7058,"lbm_writes_lt_1ms":98,"reinsert_count":0,"update_count":475}
I20260812 06:19:09.421213  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:09.578539  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.157s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1263,"lbm_read_time_us":11060,"lbm_reads_lt_1ms":464,"lbm_write_time_us":27697,"lbm_writes_lt_1ms":443,"mutex_wait_us":230,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":339,"threads_started":5,"update_count":2000}
I20260812 06:19:09.579226  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:09.634704  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.055s	user 0.029s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":19961,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:09.635360  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:09.648841  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5218,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.649489  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:09.823758  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.174s	user 0.094s	sys 0.080s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":251,"lbm_read_time_us":12989,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29202,"lbm_writes_lt_1ms":443,"mutex_wait_us":3,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2000}
I20260812 06:19:09.824389  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=11.118625
I20260812 06:19:09.862368  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.038s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16576,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.862886  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:09.877144  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5571,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.877741  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.008320  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.130s	user 0.107s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672269,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":9474,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23953,"lbm_writes_lt_1ms":443,"mutex_wait_us":25,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18816,"update_count":2000}
I20260812 06:19:10.008981  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:10.050305  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.041s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16648,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.050880  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:10.065575  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.014s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6122,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.066015  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.194784  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.129s	user 0.104s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":722,"lbm_read_time_us":10445,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25070,"lbm_writes_lt_1ms":443,"mutex_wait_us":327,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:10.195281  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:10.250610  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.055s	user 0.021s	sys 0.027s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16719,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.251299  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:10.262149  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4329,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.262653  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.426352  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.164s	user 0.107s	sys 0.056s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":13266,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25067,"lbm_writes_lt_1ms":443,"mutex_wait_us":42,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:10.427188  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:10.477260  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.050s	user 0.014s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15951,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.477797  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:10.489990  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4442,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.490459  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.628703  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.138s	user 0.120s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":975,"lbm_read_time_us":10137,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27995,"lbm_writes_lt_1ms":443,"mutex_wait_us":73,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:19:10.629243  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:10.678059  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.049s	user 0.011s	sys 0.033s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":23043,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.678596  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:10.691358  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.013s	user 0.009s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4893,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.691891  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushMRSOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.726020  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushMRSOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.034s	user 0.032s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":72,"dirs.run_cpu_time_us":260,"dirs.run_wall_time_us":1387,"drs_written":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1712,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:10.726764  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling LogGCOp(2632e2f2e0f64e16a06853002162077e): free 112692375 bytes of WAL
I20260812 06:19:10.727010  5824 log_reader.cc:385] T 2632e2f2e0f64e16a06853002162077e: removed 11 log segments from log reader
I20260812 06:19:10.727078  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000003 (ops 12-16)
I20260812 06:19:10.727201  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000004 (ops 17-21)
I20260812 06:19:10.727263  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000005 (ops 22-26)
I20260812 06:19:10.727311  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000006 (ops 27-31)
I20260812 06:19:10.727355  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000007 (ops 32-36)
I20260812 06:19:10.727398  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000008 (ops 37-41)
I20260812 06:19:10.727440  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000009 (ops 42-46)
I20260812 06:19:10.727480  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000010 (ops 47-51)
I20260812 06:19:10.727520  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000011 (ops 52-56)
I20260812 06:19:10.727562  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000012 (ops 57-61)
I20260812 06:19:10.727603  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000013 (ops 62-66)
I20260812 06:19:10.759491  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: LogGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.033s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:19:10.760007  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=3.181125
I20260812 06:19:10.773375  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4594951,"delete_count":0,"lbm_write_time_us":5202,"lbm_writes_lt_1ms":115,"reinsert_count":0,"update_count":560}
I20260812 06:19:10.773864  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e): 447 bytes on disk
I20260812 06:19:10.774400  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e) 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:19:10.774891  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:10.789335  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":3610355,"delete_count":0,"lbm_write_time_us":5328,"lbm_writes_lt_1ms":91,"reinsert_count":0,"update_count":440}
I20260812 06:19:10.790166  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:10.961181  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.171s	user 0.126s	sys 0.043s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877328,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1077,"lbm_read_time_us":13129,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32229,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":22784,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:19:10.961951  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:11.018042  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.056s	user 0.036s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26770,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.018580  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:11.036507  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.018s	user 0.015s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7205,"lbm_writes_lt_1ms":103,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":500}
I20260812 06:19:11.036993  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:11.214329  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.177s	user 0.121s	sys 0.055s 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":1646,"lbm_read_time_us":11107,"lbm_reads_lt_1ms":564,"lbm_write_time_us":33556,"lbm_writes_lt_1ms":543,"mutex_wait_us":409,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.215085  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:11.271130  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.056s	user 0.031s	sys 0.021s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23307,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.271675  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:11.431056  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.159s	user 0.105s	sys 0.051s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672160,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":340,"lbm_read_time_us":12890,"lbm_reads_lt_1ms":463,"lbm_write_time_us":27707,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2000}
I20260812 06:19:11.432219  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:11.485198  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.053s	user 0.031s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":23949,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.485785  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:11.497541  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4331,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.498030  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:11.688755  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.191s	user 0.129s	sys 0.051s 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":174,"lbm_read_time_us":11169,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28847,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2500}
I20260812 06:19:11.689446  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:11.740911  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.051s	user 0.043s	sys 0.004s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21385,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.741366  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:11.753437  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4279,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.754127  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:11.911015  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.157s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":12199,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30287,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12416,"update_count":2500}
I20260812 06:19:11.911692  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=11.118625
I20260812 06:19:11.967701  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.056s	user 0.033s	sys 0.007s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":17794,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:11.968138  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=6.157687
I20260812 06:19:11.988356  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.020s	user 0.014s	sys 0.004s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8656,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:11.988878  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:12.155380  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.166s	user 0.110s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774694,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1014,"lbm_read_time_us":11743,"lbm_reads_lt_1ms":572,"lbm_write_time_us":33727,"lbm_writes_lt_1ms":543,"mutex_wait_us":324,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10496,"update_count":2500}
I20260812 06:19:12.156265  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:12.203737  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.047s	user 0.022s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20688,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.204519  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:12.218011  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.013s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5320,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.218505  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushMRSOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:12.246552  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushMRSOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":41,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1302,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1530,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:12.247293  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling LogGCOp(2632e2f2e0f64e16a06853002162077e): free 124257197 bytes of WAL
I20260812 06:19:12.247555  5824 log_reader.cc:385] T 2632e2f2e0f64e16a06853002162077e: removed 12 log segments from log reader
I20260812 06:19:12.247622  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000014 (ops 67-70)
I20260812 06:19:12.247674  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000015 (ops 71-75)
I20260812 06:19:12.247731  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000016 (ops 76-80)
I20260812 06:19:12.247772  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000017 (ops 81-85)
I20260812 06:19:12.247807  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000018 (ops 86-90)
I20260812 06:19:12.247844  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000019 (ops 91-95)
I20260812 06:19:12.247881  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000020 (ops 96-100)
I20260812 06:19:12.247931  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000021 (ops 101-105)
I20260812 06:19:12.247965  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000022 (ops 106-110)
I20260812 06:19:12.248003  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000023 (ops 111-115)
I20260812 06:19:12.248037  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000024 (ops 116-120)
I20260812 06:19:12.248075  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000025 (ops 121-125)
I20260812 06:19:12.274991  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: LogGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.028s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:12.275602  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e): 482 bytes on disk
I20260812 06:19:12.276196  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":97,"lbm_reads_lt_1ms":4}
I20260812 06:19:12.276763  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=3.181125
I20260812 06:19:12.289759  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.013s	user 0.001s	sys 0.009s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4626,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:12.290143  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling LogGCOp(2632e2f2e0f64e16a06853002162077e): free 12017991 bytes of WAL
I20260812 06:19:12.290325  5824 log_reader.cc:385] T 2632e2f2e0f64e16a06853002162077e: removed 1 log segments from log reader
I20260812 06:19:12.290385  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000026 (ops 126-130)
I20260812 06:19:12.292840  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: LogGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:12.293128  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:12.304823  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4145,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.305330  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:12.527340  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.222s	user 0.127s	sys 0.085s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":849,"lbm_read_time_us":15507,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37862,"lbm_writes_lt_1ms":743,"mutex_wait_us":355,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":24704,"thread_start_us":79,"threads_started":1,"update_count":3500}
I20260812 06:19:12.528081  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=15.087375
I20260812 06:19:12.609409  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.081s	user 0.030s	sys 0.039s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":29375,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:19:12.609953  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=6.157687
I20260812 06:19:12.631247  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":8779,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:12.631879  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:12.831360  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.199s	user 0.134s	sys 0.065s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877100,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1192,"lbm_read_time_us":13906,"lbm_reads_lt_1ms":672,"lbm_write_time_us":36769,"lbm_writes_lt_1ms":643,"mutex_wait_us":504,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:19:12.832073  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:12.889729  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.057s	user 0.021s	sys 0.032s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":26415,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.890261  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:12.901160  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4369,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.901767  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:13.098138  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.196s	user 0.111s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":290,"lbm_read_time_us":13666,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30830,"lbm_writes_lt_1ms":543,"mutex_wait_us":53,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:13.098935  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:13.160818  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.062s	user 0.032s	sys 0.026s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22781,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.161441  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.172448  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4239,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.172881  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:13.365108  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.192s	user 0.130s	sys 0.055s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":13830,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32108,"lbm_writes_lt_1ms":543,"mutex_wait_us":49,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8832,"update_count":2500}
I20260812 06:19:13.365866  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=11.118625
I20260812 06:19:13.402115  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.036s	user 0.017s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":15996,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:13.402747  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.428568  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.026s	user 0.010s	sys 0.013s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5512,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.429181  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:13.594893  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.165s	user 0.117s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672270,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":219,"lbm_read_time_us":12026,"lbm_reads_lt_1ms":464,"lbm_write_time_us":24421,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":2000}
I20260812 06:19:13.595606  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:13.651889  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.056s	user 0.045s	sys 0.003s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22322,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.652448  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.664248  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.012s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4072,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.664794  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:13.824971  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.160s	user 0.123s	sys 0.033s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":717,"lbm_read_time_us":11452,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31888,"lbm_writes_lt_1ms":543,"mutex_wait_us":70,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":135552,"update_count":2500}
I20260812 06:19:13.825467  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=14.095187
I20260812 06:19:13.874219  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.049s	user 0.020s	sys 0.025s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21366,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.874761  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.890127  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.015s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5621,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.890653  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushMRSOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:13.920858  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushMRSOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":51,"dirs.run_cpu_time_us":190,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1771,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:13.921609  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling LogGCOp(2632e2f2e0f64e16a06853002162077e): free 124710562 bytes of WAL
I20260812 06:19:13.921882  5824 log_reader.cc:385] T 2632e2f2e0f64e16a06853002162077e: removed 12 log segments from log reader
I20260812 06:19:13.921963  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000027 (ops 131-135)
I20260812 06:19:13.922061  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000028 (ops 136-140)
I20260812 06:19:13.922101  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000029 (ops 141-145)
I20260812 06:19:13.922129  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000030 (ops 146-150)
I20260812 06:19:13.922166  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000031 (ops 151-155)
I20260812 06:19:13.922195  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000032 (ops 156-160)
I20260812 06:19:13.922225  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000033 (ops 161-165)
I20260812 06:19:13.922256  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000034 (ops 166-170)
I20260812 06:19:13.922290  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000035 (ops 171-175)
I20260812 06:19:13.922323  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000036 (ops 176-180)
I20260812 06:19:13.922353  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000037 (ops 181-185)
I20260812 06:19:13.922389  5824 log.cc:1079] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Deleting log segment in path: /tmp/dist-test-taskDWxOAz/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515542668259-5302-0/minicluster-data/ts-0-root/wals/2632e2f2e0f64e16a06853002162077e/wal-000000038 (ops 186-190)
I20260812 06:19:13.953473  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: LogGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.032s	user 0.000s	sys 0.029s Metrics: {}
I20260812 06:19:13.954074  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e): 492 bytes on disk
I20260812 06:19:13.954614  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: UndoDeltaBlockGCOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:13.955534  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.975816  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.020s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6565,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.976359  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=2.188937
I20260812 06:19:13.987231  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.011s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4449,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.987797  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e): perf score=1.000000
I20260812 06:19:14.141680  5302 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.086s	user 1.873s	sys 0.207s
I20260812 06:19:14.202728  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: MajorDeltaCompactionOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.215s	user 0.151s	sys 0.055s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14802,"lbm_reads_lt_1ms":770,"lbm_write_time_us":39915,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":9216,"update_count":3500}
I20260812 06:19:14.203531  5940 maintenance_manager.cc:419] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: Scheduling FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e): perf score=10.126437
I20260812 06:19:14.231796  5302 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.090s	user 0.004s	sys 0.000s
I20260812 06:19:14.232399  5302 tablet_server.cc:179] TabletServer@127.5.45.129:0 shutting down...
I20260812 06:19:14.241881  5824 maintenance_manager.cc:643] P 0f3eb4dbb77c4b91bfff0d42e6ef1925: FlushDeltaMemStoresOp(2632e2f2e0f64e16a06853002162077e) complete. Timing: real 0.038s	user 0.031s	sys 0.005s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":16323,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:14.242362  5302 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:14.242583  5302 tablet_replica.cc:333] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925: stopping tablet replica
I20260812 06:19:14.242710  5302 raft_consensus.cc:2243] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:14.242885  5302 raft_consensus.cc:2272] T 2632e2f2e0f64e16a06853002162077e P 0f3eb4dbb77c4b91bfff0d42e6ef1925 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:14.247707  5302 tablet_server.cc:196] TabletServer@127.5.45.129:0 shutdown complete.
I20260812 06:19:14.270905  5302 master.cc:562] Master@127.5.45.190:36213 shutting down...
I20260812 06:19:14.274310  5302 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:14.274480  5302 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:14.274531  5302 tablet_replica.cc:333] T 00000000000000000000000000000000 P 367cd7e0f74c49c7beb04d86bbae7f68: stopping tablet replica
I20260812 06:19:14.286929  5302 master.cc:584] Master@127.5.45.190:36213 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5563 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11702 ms total)

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