[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:18:53.849748  9426 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.52.190:41891
I20260812 06:18:53.850891  9426 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:18:53.851572  9426 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.859221  9435 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.859236  9434 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.859495  9426 server_base.cc:1061] running on GCE node
W20260812 06:18:53.859542  9441 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.860133  9426 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.860268  9426 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.860324  9426 hybrid_clock.cc:648] HybridClock initialized: now 1786515533860321 us; error 0 us; skew 500 ppm
I20260812 06:18:53.862432  9426 webserver.cc:533] Webserver started at http://127.9.52.190:39961/ using document root <none> and password file <none>
I20260812 06:18:53.863077  9426 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.863188  9426 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.863494  9426 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.865413  9426 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/master-0-root/instance:
uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-6ntk"
I20260812 06:18:53.869561  9426 fs_manager.cc:696] Time spent creating directory manager: real 0.004s	user 0.003s	sys 0.000s
I20260812 06:18:53.872263  9448 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.873574  9426 fs_manager.cc:730] Time spent opening block manager: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:18:53.873688  9426 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/master-0-root
uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-6ntk"
I20260812 06:18:53.873782  9426 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:53.888999  9426 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:53.889684  9426 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:18:53.889845  9426 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:53.898438  9426 rpc_server.cc:307] RPC server started. Bound to: 127.9.52.190:41891
I20260812 06:18:53.898434  9521 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.52.190:41891 every 8 connection(s)
I20260812 06:18:53.901043  9522 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:53.906814  9522 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: Bootstrap starting.
I20260812 06:18:53.909459  9522 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:53.910589  9522 log.cc:826] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:53.912619  9522 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: No bootstrap required, opened a new log
I20260812 06:18:53.915684  9522 raft_consensus.cc:359] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER }
I20260812 06:18:53.915915  9522 raft_consensus.cc:385] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:53.916031  9522 raft_consensus.cc:740] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: d63189cdae2b4ffa9f9a9dbf29a4a6d5, State: Initialized, Role: FOLLOWER
I20260812 06:18:53.916682  9522 consensus_queue.cc:260] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [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: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER }
I20260812 06:18:53.916875  9522 raft_consensus.cc:399] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:53.916967  9522 raft_consensus.cc:493] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:53.917127  9522 raft_consensus.cc:3060] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:53.918030  9522 raft_consensus.cc:515] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER }
I20260812 06:18:53.918515  9522 leader_election.cc:304] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [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: d63189cdae2b4ffa9f9a9dbf29a4a6d5; no voters: 
I20260812 06:18:53.918880  9522 leader_election.cc:290] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:53.919090  9528 raft_consensus.cc:2804] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:53.919414  9528 raft_consensus.cc:697] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 1 LEADER]: Becoming Leader. State: Replica: d63189cdae2b4ffa9f9a9dbf29a4a6d5, State: Running, Role: LEADER
I20260812 06:18:53.919821  9528 consensus_queue.cc:237] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [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: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER }
I20260812 06:18:53.920040  9522 sys_catalog.cc:565] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:53.921916  9531 sys_catalog.cc:455] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [sys.catalog]: SysCatalogTable state changed. Reason: New leader d63189cdae2b4ffa9f9a9dbf29a4a6d5. Latest consensus state: current_term: 1 leader_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER } }
I20260812 06:18:53.921948  9530 sys_catalog.cc:455] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "d63189cdae2b4ffa9f9a9dbf29a4a6d5" member_type: VOTER } }
I20260812 06:18:53.922034  9531 sys_catalog.cc:458] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.922055  9530 sys_catalog.cc:458] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:53.922406  9548 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:53.922607  9426 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:53.924875  9548 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:53.930071  9548 catalog_manager.cc:1383] Generated new cluster ID: 50bbfa601cfd4b219dc8d9725dcac447
I20260812 06:18:53.930166  9548 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:53.953991  9548 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:53.955286  9548 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:53.968350  9548 catalog_manager.cc:6092] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: Generated new TSK 0
I20260812 06:18:53.969211  9548 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:53.987583  9426 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:53.990377  9558 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.990413  9560 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:53.990654  9556 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:53.990877  9426 server_base.cc:1061] running on GCE node
I20260812 06:18:53.991050  9426 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:53.991098  9426 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:53.991120  9426 hybrid_clock.cc:648] HybridClock initialized: now 1786515533991120 us; error 0 us; skew 500 ppm
I20260812 06:18:53.992148  9426 webserver.cc:533] Webserver started at http://127.9.52.129:45485/ using document root <none> and password file <none>
I20260812 06:18:53.992326  9426 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:53.992391  9426 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:53.992471  9426 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:53.992954  9426 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/instance:
uuid: "037fd9695a7840ba83ece1db2c6bdcae"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-6ntk"
I20260812 06:18:53.994918  9426 fs_manager.cc:696] Time spent creating directory manager: real 0.002s	user 0.000s	sys 0.003s
I20260812 06:18:53.996081  9570 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:53.996384  9426 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:18:53.996454  9426 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root
uuid: "037fd9695a7840ba83ece1db2c6bdcae"
format_stamp: "Formatted at 2026-08-12 06:18:53 on dist-test-slave-6ntk"
I20260812 06:18:53.996546  9426 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:54.020012  9426 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:54.020776  9426 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:54.021396  9426 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:54.022429  9426 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:54.022486  9426 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.022560  9426 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:54.022607  9426 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:54.029425  9426 rpc_server.cc:307] RPC server started. Bound to: 127.9.52.129:33927
I20260812 06:18:54.029484  9662 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.52.129:33927 every 8 connection(s)
I20260812 06:18:54.044579  9663 heartbeater.cc:344] Connected to a master server at 127.9.52.190:41891
I20260812 06:18:54.044895  9663 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:54.045439  9663 heartbeater.cc:507] Master 127.9.52.190:41891 requested a full tablet report, sending...
I20260812 06:18:54.047096  9469 ts_manager.cc:194] Registered new tserver with Master: 037fd9695a7840ba83ece1db2c6bdcae (127.9.52.129:33927)
I20260812 06:18:54.047379  9426 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.017267016s
I20260812 06:18:54.048462  9469 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:45928
I20260812 06:18:54.058565  9469 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:45942:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:54.075666  9605 tablet_service.cc:1511] Processing CreateTablet for tablet 94e20166260e4fc095ddf24d833ead7f (DEFAULT_TABLE table=heavy-update-compaction-test [id=f340bd7fad304d4d8869ac2a37c0c057]), partition=
I20260812 06:18:54.076259  9605 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 94e20166260e4fc095ddf24d833ead7f. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:54.078784  9686 tablet_bootstrap.cc:492] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Bootstrap starting.
I20260812 06:18:54.080430  9686 tablet_bootstrap.cc:654] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:54.081787  9686 tablet_bootstrap.cc:492] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: No bootstrap required, opened a new log
I20260812 06:18:54.081938  9686 ts_tablet_manager.cc:1403] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Time spent bootstrapping tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:54.082456  9686 raft_consensus.cc:359] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "037fd9695a7840ba83ece1db2c6bdcae" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 33927 } }
I20260812 06:18:54.082588  9686 raft_consensus.cc:385] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:54.082635  9686 raft_consensus.cc:740] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 037fd9695a7840ba83ece1db2c6bdcae, State: Initialized, Role: FOLLOWER
I20260812 06:18:54.082820  9686 consensus_queue.cc:260] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [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: "037fd9695a7840ba83ece1db2c6bdcae" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 33927 } }
I20260812 06:18:54.082942  9686 raft_consensus.cc:399] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:54.083000  9686 raft_consensus.cc:493] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:54.083065  9686 raft_consensus.cc:3060] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:54.084110  9686 raft_consensus.cc:515] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "037fd9695a7840ba83ece1db2c6bdcae" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 33927 } }
I20260812 06:18:54.084270  9686 leader_election.cc:304] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [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: 037fd9695a7840ba83ece1db2c6bdcae; no voters: 
I20260812 06:18:54.084519  9686 leader_election.cc:290] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:54.084628  9689 raft_consensus.cc:2804] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:54.084897  9686 ts_tablet_manager.cc:1434] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:18:54.084877  9689 raft_consensus.cc:697] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 1 LEADER]: Becoming Leader. State: Replica: 037fd9695a7840ba83ece1db2c6bdcae, State: Running, Role: LEADER
I20260812 06:18:54.085062  9689 consensus_queue.cc:237] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [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: "037fd9695a7840ba83ece1db2c6bdcae" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 33927 } }
I20260812 06:18:54.085170  9663 heartbeater.cc:499] Master 127.9.52.190:41891 was elected leader, sending a full tablet report...
I20260812 06:18:54.088207  9469 catalog_manager.cc:5719] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae reported cstate change: term changed from 0 to 1, leader changed from <none> to 037fd9695a7840ba83ece1db2c6bdcae (127.9.52.129). New cstate: current_term: 1 leader_uuid: "037fd9695a7840ba83ece1db2c6bdcae" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "037fd9695a7840ba83ece1db2c6bdcae" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 33927 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:54.151060  9426 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.017s	sys 0.008s
I20260812 06:18:54.280629  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushMRSOp(94e20166260e4fc095ddf24d833ead7f): perf score=15.086190
I20260812 06:18:54.419570  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushMRSOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.139s	user 0.093s	sys 0.044s Metrics: {"bytes_written":8533272,"cfile_init":1,"compiler_manager_pool.queue_time_us":296,"delete_count":0,"dirs.queue_time_us":82,"dirs.run_cpu_time_us":225,"dirs.run_wall_time_us":941,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":34219,"lbm_writes_lt_1ms":575,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":196864,"thread_start_us":121,"threads_started":1,"update_count":1040}
I20260812 06:18:54.420884  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling LogGCOp(94e20166260e4fc095ddf24d833ead7f): free 20743880 bytes of WAL
I20260812 06:18:54.421288  9576 log_reader.cc:385] T 94e20166260e4fc095ddf24d833ead7f: removed 2 log segments from log reader
I20260812 06:18:54.421379  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000001 (ops 1-6)
I20260812 06:18:54.421478  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000002 (ops 7-11)
I20260812 06:18:54.427870  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: LogGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.007s	user 0.000s	sys 0.005s Metrics: {}
I20260812 06:18:54.428316  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:54.443660  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.015s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3364205,"delete_count":0,"lbm_write_time_us":4272,"lbm_writes_lt_1ms":85,"reinsert_count":0,"update_count":410}
I20260812 06:18:54.444205  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f): 12719216 bytes on disk
I20260812 06:18:54.444901  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":96,"lbm_reads_lt_1ms":4}
I20260812 06:18:54.445508  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:54.558145  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.112s	user 0.082s	sys 0.029s Metrics: {"cfile_cache_miss":322,"cfile_cache_miss_bytes":16159605,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":8028,"lbm_reads_lt_1ms":350,"lbm_write_time_us":20095,"lbm_writes_lt_1ms":333,"peak_mem_usage":36812022,"reinsert_count":0,"thread_start_us":323,"threads_started":5,"update_count":1450}
I20260812 06:18:54.558720  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:54.606391  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.048s	user 0.024s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15912,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.606849  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:54.618875  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.619621  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:54.749255  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.129s	user 0.089s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":659,"lbm_read_time_us":10152,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26093,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:18:54.750005  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:54.808776  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.059s	user 0.017s	sys 0.026s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16306,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:54.809486  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:54.821676  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4712,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:54.822336  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:54.984220  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.162s	user 0.108s	sys 0.053s 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":548,"lbm_read_time_us":12286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":27142,"lbm_writes_lt_1ms":443,"mutex_wait_us":330,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":21248,"update_count":2000}
I20260812 06:18:54.985005  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:55.028980  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.044s	user 0.020s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16952,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.029556  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:55.041160  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4112,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.041855  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:55.181737  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.140s	user 0.102s	sys 0.037s 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":179,"lbm_read_time_us":9979,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26861,"lbm_writes_lt_1ms":443,"mutex_wait_us":66,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":14080,"update_count":2000}
I20260812 06:18:55.182333  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:55.228792  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.046s	user 0.030s	sys 0.003s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15904,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.229317  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:55.240368  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4154,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.240931  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:55.369060  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.128s	user 0.102s	sys 0.025s 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":1170,"lbm_read_time_us":9547,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24486,"lbm_writes_lt_1ms":443,"mutex_wait_us":350,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2000}
I20260812 06:18:55.369598  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:55.422586  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.053s	user 0.034s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":17778,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.423184  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:55.434006  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.434506  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:55.586746  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.152s	user 0.115s	sys 0.036s 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":672,"lbm_read_time_us":12119,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23828,"lbm_writes_lt_1ms":443,"mutex_wait_us":134,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:18:55.587416  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:55.627978  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.040s	user 0.016s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15360,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.628500  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:55.640403  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.000s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4399,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.641021  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:55.775686  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.134s	user 0.091s	sys 0.043s 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":167,"lbm_read_time_us":10828,"lbm_reads_lt_1ms":472,"lbm_write_time_us":24176,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13056,"update_count":2000}
I20260812 06:18:55.776384  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:55.818428  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.042s	user 0.026s	sys 0.016s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":18373,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:55.819064  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:55.832872  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.014s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:55.833410  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushMRSOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:55.869393  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushMRSOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.036s	user 0.034s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":237,"dirs.run_wall_time_us":1607,"drs_written":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1715,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30,"spinlock_wait_cycles":1408}
I20260812 06:18:55.870407  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling LogGCOp(94e20166260e4fc095ddf24d833ead7f): free 124257249 bytes of WAL
I20260812 06:18:55.870678  9576 log_reader.cc:385] T 94e20166260e4fc095ddf24d833ead7f: removed 12 log segments from log reader
I20260812 06:18:55.870748  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000003 (ops 12-16)
I20260812 06:18:55.870810  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000004 (ops 17-21)
I20260812 06:18:55.870883  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000005 (ops 22-26)
I20260812 06:18:55.870929  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000006 (ops 27-31)
I20260812 06:18:55.870971  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000007 (ops 32-36)
I20260812 06:18:55.871013  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000008 (ops 37-40)
I20260812 06:18:55.871057  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000009 (ops 41-45)
I20260812 06:18:55.871094  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000010 (ops 46-50)
I20260812 06:18:55.871136  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000011 (ops 51-55)
I20260812 06:18:55.871176  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000012 (ops 56-60)
I20260812 06:18:55.871217  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000013 (ops 61-65)
I20260812 06:18:55.871258  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000014 (ops 66-70)
I20260812 06:18:55.903793  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: LogGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.033s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:18:55.904328  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f): 473 bytes on disk
I20260812 06:18:55.904976  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":77,"lbm_reads_lt_1ms":4}
I20260812 06:18:55.905524  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=6.157687
I20260812 06:18:55.934217  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.028s	user 0.012s	sys 0.011s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10108,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:18:55.934718  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:56.106801  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.172s	user 0.119s	sys 0.051s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877220,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":903,"lbm_read_time_us":11921,"lbm_reads_lt_1ms":665,"lbm_write_time_us":34160,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7936,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:18:56.107684  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:56.169925  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.062s	user 0.030s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":28354,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.170569  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:56.199069  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.028s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.199745  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:56.211320  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4183,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.212005  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:56.384481  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.172s	user 0.121s	sys 0.050s 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":1943,"lbm_read_time_us":12087,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37937,"lbm_writes_lt_1ms":643,"mutex_wait_us":788,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":3000}
I20260812 06:18:56.385121  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:56.438141  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.053s	user 0.041s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23374,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.438758  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:56.450865  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.451611  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:56.616318  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.164s	user 0.139s	sys 0.023s 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":323,"lbm_read_time_us":12383,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32056,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:18:56.617019  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:56.652403  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.035s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15160,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:56.653023  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:56.675262  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.022s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":7332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.675796  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:56.852645  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.177s	user 0.117s	sys 0.054s 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":182,"lbm_read_time_us":10615,"lbm_reads_lt_1ms":464,"lbm_write_time_us":31048,"lbm_writes_lt_1ms":443,"mutex_wait_us":79,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5376,"update_count":2000}
I20260812 06:18:56.853406  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:56.912364  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.059s	user 0.027s	sys 0.026s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20792,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:56.912973  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:56.924242  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4388,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:56.924779  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:57.122643  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.198s	user 0.118s	sys 0.075s 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":345,"lbm_read_time_us":14551,"lbm_reads_lt_1ms":572,"lbm_write_time_us":37068,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":61,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.126300  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:57.177337  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.051s	user 0.021s	sys 0.020s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":20705,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:18:57.177963  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:57.192126  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.014s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4866,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.192778  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:57.392539  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.200s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":460,"lbm_read_time_us":14532,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32758,"lbm_writes_lt_1ms":543,"mutex_wait_us":71,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:18:57.393134  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=11.118625
I20260812 06:18:57.427956  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.035s	user 0.009s	sys 0.024s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":15245,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:57.428640  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:57.444096  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5605,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:57.444579  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushMRSOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:57.475698  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushMRSOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1275449,"cfile_init":1,"dirs.queue_time_us":79,"dirs.run_cpu_time_us":211,"dirs.run_wall_time_us":1259,"drs_written":1,"lbm_read_time_us":39,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1515,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:18:57.476519  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling LogGCOp(94e20166260e4fc095ddf24d833ead7f): free 121006384 bytes of WAL
I20260812 06:18:57.476783  9576 log_reader.cc:385] T 94e20166260e4fc095ddf24d833ead7f: removed 12 log segments from log reader
I20260812 06:18:57.476866  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000015 (ops 71-75)
I20260812 06:18:57.476922  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000016 (ops 76-80)
I20260812 06:18:57.476953  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000017 (ops 81-85)
I20260812 06:18:57.476981  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000018 (ops 86-90)
I20260812 06:18:57.476999  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000019 (ops 91-95)
I20260812 06:18:57.477047  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000020 (ops 96-100)
I20260812 06:18:57.477070  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000021 (ops 101-105)
I20260812 06:18:57.477099  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000022 (ops 106-110)
I20260812 06:18:57.477145  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000023 (ops 111-115)
I20260812 06:18:57.477170  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000024 (ops 116-120)
I20260812 06:18:57.477203  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000025 (ops 121-124)
I20260812 06:18:57.477248  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000026 (ops 125-129)
I20260812 06:18:57.503610  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: LogGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.027s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:18:57.504140  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=3.181125
I20260812 06:18:57.527084  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.023s	user 0.006s	sys 0.015s Metrics: {"bytes_written":5128262,"delete_count":0,"lbm_write_time_us":5632,"lbm_writes_lt_1ms":128,"reinsert_count":0,"update_count":625}
I20260812 06:18:57.527679  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling LogGCOp(94e20166260e4fc095ddf24d833ead7f): free 12018006 bytes of WAL
I20260812 06:18:57.527930  9576 log_reader.cc:385] T 94e20166260e4fc095ddf24d833ead7f: removed 1 log segments from log reader
I20260812 06:18:57.527977  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000027 (ops 130-134)
I20260812 06:18:57.530545  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: LogGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.003s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:57.530889  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.196750
I20260812 06:18:57.539620  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3077030,"delete_count":0,"lbm_write_time_us":3100,"lbm_writes_lt_1ms":78,"reinsert_count":0,"update_count":375}
I20260812 06:18:57.540135  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:57.752149  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.212s	user 0.119s	sys 0.092s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877304,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1586,"lbm_read_time_us":15548,"lbm_reads_lt_1ms":674,"lbm_write_time_us":37627,"lbm_writes_lt_1ms":643,"mutex_wait_us":876,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:18:57.753226  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:57.815781  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.062s	user 0.039s	sys 0.019s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21232,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:57.816401  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f): 482 bytes on disk
I20260812 06:18:57.816890  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:18:57.817418  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:57.828289  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4244,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:57.828740  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:58.042479  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.214s	user 0.125s	sys 0.075s 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":202,"lbm_read_time_us":14075,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32551,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3712,"update_count":2500}
I20260812 06:18:58.043079  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:58.103019  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.060s	user 0.025s	sys 0.024s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":22038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.103631  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:58.120083  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.016s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6090,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.120811  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:58.316634  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.196s	user 0.118s	sys 0.059s 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":617,"lbm_read_time_us":12952,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28132,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2500}
I20260812 06:18:58.317323  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:58.373180  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.056s	user 0.031s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22364,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.373735  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:58.386195  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4347,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.386747  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:58.560155  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.173s	user 0.114s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":707,"lbm_read_time_us":12436,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30871,"lbm_writes_lt_1ms":543,"mutex_wait_us":59,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14592,"update_count":2500}
I20260812 06:18:58.560948  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=14.095187
I20260812 06:18:58.606717  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.046s	user 0.030s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20578,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:58.607266  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:58.619030  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4356,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.619683  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:58.756404  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.136s	user 0.095s	sys 0.041s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":273,"lbm_read_time_us":9611,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28353,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:18:58.757162  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:58.792452  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.035s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15105,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.792981  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:58.805106  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4571,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.807287  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:58.940874  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.133s	user 0.125s	sys 0.008s 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":432,"lbm_read_time_us":9287,"lbm_reads_lt_1ms":472,"lbm_write_time_us":26736,"lbm_writes_lt_1ms":443,"mutex_wait_us":67,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":16256,"update_count":2000}
I20260812 06:18:58.941545  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:58.990679  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.049s	user 0.022s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":16893,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.991221  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:59.002082  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4035,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.002885  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushMRSOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:59.034825  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushMRSOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.032s	user 0.031s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":83,"dirs.run_cpu_time_us":279,"dirs.run_wall_time_us":1508,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2141,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:18:59.035512  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling LogGCOp(94e20166260e4fc095ddf24d833ead7f): free 120553644 bytes of WAL
I20260812 06:18:59.035760  9576 log_reader.cc:385] T 94e20166260e4fc095ddf24d833ead7f: removed 12 log segments from log reader
I20260812 06:18:59.035807  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000028 (ops 135-139)
I20260812 06:18:59.035868  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000029 (ops 140-144)
I20260812 06:18:59.035912  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000030 (ops 145-149)
I20260812 06:18:59.035955  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000031 (ops 150-154)
I20260812 06:18:59.036000  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000032 (ops 155-159)
I20260812 06:18:59.036046  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000033 (ops 160-164)
I20260812 06:18:59.036082  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000034 (ops 165-168)
I20260812 06:18:59.036123  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000035 (ops 169-173)
I20260812 06:18:59.036159  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000036 (ops 174-178)
I20260812 06:18:59.036197  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000037 (ops 179-183)
I20260812 06:18:59.036238  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000038 (ops 184-188)
I20260812 06:18:59.036278  9576 log.cc:1079] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/94e20166260e4fc095ddf24d833ead7f/wal-000000039 (ops 189-192)
I20260812 06:18:59.064879  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: LogGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.029s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:18:59.065348  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f): 475 bytes on disk
I20260812 06:18:59.066051  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: UndoDeltaBlockGCOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":127,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.066733  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=3.181125
I20260812 06:18:59.087821  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4471875,"delete_count":0,"lbm_write_time_us":7699,"lbm_writes_lt_1ms":112,"reinsert_count":0,"update_count":545}
I20260812 06:18:59.088364  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=2.188937
I20260812 06:18:59.100289  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":3733434,"delete_count":0,"lbm_write_time_us":4396,"lbm_writes_lt_1ms":94,"reinsert_count":0,"update_count":455}
I20260812 06:18:59.100965  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:59.213068  9426 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.062s	user 1.827s	sys 0.133s
I20260812 06:18:59.273615  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.172s	user 0.139s	sys 0.032s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877330,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":12729,"lbm_reads_lt_1ms":670,"lbm_write_time_us":35493,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:18:59.274158  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f): perf score=10.126437
I20260812 06:18:59.301290  9426 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.087s	user 0.002s	sys 0.000s
I20260812 06:18:59.302124  9426 tablet_server.cc:179] TabletServer@127.9.52.129:0 shutting down...
I20260812 06:18:59.307711  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: FlushDeltaMemStoresOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.033s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14170,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.308375  9664 maintenance_manager.cc:419] P 037fd9695a7840ba83ece1db2c6bdcae: Scheduling MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f): perf score=1.000000
I20260812 06:18:59.402196  9576 maintenance_manager.cc:643] P 037fd9695a7840ba83ece1db2c6bdcae: MajorDeltaCompactionOp(94e20166260e4fc095ddf24d833ead7f) complete. Timing: real 0.094s	user 0.059s	sys 0.032s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16569746,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":4734,"lbm_read_time_us":6833,"lbm_reads_lt_1ms":367,"lbm_write_time_us":17341,"lbm_writes_lt_1ms":343,"mutex_wait_us":2019,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":1500}
I20260812 06:18:59.403093  9426 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:18:59.403580  9426 tablet_replica.cc:333] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae: stopping tablet replica
I20260812 06:18:59.403867  9426 raft_consensus.cc:2243] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.404134  9426 raft_consensus.cc:2272] T 94e20166260e4fc095ddf24d833ead7f P 037fd9695a7840ba83ece1db2c6bdcae [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.419749  9426 tablet_server.cc:196] TabletServer@127.9.52.129:0 shutdown complete.
I20260812 06:18:59.431499  9426 master.cc:562] Master@127.9.52.190:41891 shutting down...
I20260812 06:18:59.435887  9426 raft_consensus.cc:2243] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:18:59.436082  9426 raft_consensus.cc:2272] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:18:59.436136  9426 tablet_replica.cc:333] T 00000000000000000000000000000000 P d63189cdae2b4ffa9f9a9dbf29a4a6d5: stopping tablet replica
I20260812 06:18:59.448916  9426 master.cc:584] Master@127.9.52.190:41891 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5702 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:18:59.566448  9426 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.9.52.190:35233
I20260812 06:18:59.566915  9426 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.569597  9717 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.569628  9714 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.569646  9715 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.569774  9426 server_base.cc:1061] running on GCE node
I20260812 06:18:59.570113  9426 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.570176  9426 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:59.570202  9426 hybrid_clock.cc:648] HybridClock initialized: now 1786515539570202 us; error 0 us; skew 500 ppm
I20260812 06:18:59.571156  9426 webserver.cc:533] Webserver started at http://127.9.52.190:44343/ using document root <none> and password file <none>
I20260812 06:18:59.571347  9426 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.571425  9426 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.571513  9426 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.571952  9426 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/master-0-root/instance:
uuid: "7cfe6d63c8ec4267b76c211a1c3de722"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-6ntk"
I20260812 06:18:59.573545  9426 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:18:59.575006  9726 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.575305  9426 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.575414  9426 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/master-0-root
uuid: "7cfe6d63c8ec4267b76c211a1c3de722"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-6ntk"
I20260812 06:18:59.575511  9426 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.585866  9426 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.586345  9426 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.590647  9426 rpc_server.cc:307] RPC server started. Bound to: 127.9.52.190:35233
I20260812 06:18:59.591221  9805 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.52.190:35233 every 8 connection(s)
I20260812 06:18:59.591835  9806 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.593571  9806 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722: Bootstrap starting.
I20260812 06:18:59.594406  9806 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.595491  9806 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722: No bootstrap required, opened a new log
I20260812 06:18:59.595846  9806 raft_consensus.cc:359] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER }
I20260812 06:18:59.595930  9806 raft_consensus.cc:385] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.595958  9806 raft_consensus.cc:740] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7cfe6d63c8ec4267b76c211a1c3de722, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.596064  9806 consensus_queue.cc:260] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [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: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER }
I20260812 06:18:59.596120  9806 raft_consensus.cc:399] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.596143  9806 raft_consensus.cc:493] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.596171  9806 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.596812  9806 raft_consensus.cc:515] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER }
I20260812 06:18:59.596923  9806 leader_election.cc:304] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [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: 7cfe6d63c8ec4267b76c211a1c3de722; no voters: 
I20260812 06:18:59.597069  9806 leader_election.cc:290] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.597214  9810 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.597519  9810 raft_consensus.cc:697] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 1 LEADER]: Becoming Leader. State: Replica: 7cfe6d63c8ec4267b76c211a1c3de722, State: Running, Role: LEADER
I20260812 06:18:59.597607  9806 sys_catalog.cc:565] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:59.597689  9810 consensus_queue.cc:237] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [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: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER }
I20260812 06:18:59.598232  9811 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER } }
I20260812 06:18:59.598282  9812 sys_catalog.cc:455] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 7cfe6d63c8ec4267b76c211a1c3de722. Latest consensus state: current_term: 1 leader_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7cfe6d63c8ec4267b76c211a1c3de722" member_type: VOTER } }
I20260812 06:18:59.598430  9812 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.598415  9811 sys_catalog.cc:458] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:59.599150  9823 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:59.599968  9823 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:59.600239  9426 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:59.601955  9823 catalog_manager.cc:1383] Generated new cluster ID: b5fdd988e98f4c1cb50f92b212c99a62
I20260812 06:18:59.602053  9823 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:59.620328  9823 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:59.620988  9823 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:59.625670  9823 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722: Generated new TSK 0
I20260812 06:18:59.625895  9823 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:59.632761  9426 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:59.634883  9838 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.634883  9840 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:18:59.635051  9843 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:18:59.635071  9426 server_base.cc:1061] running on GCE node
I20260812 06:18:59.635314  9426 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:59.635371  9426 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:18:59.635396  9426 hybrid_clock.cc:648] HybridClock initialized: now 1786515539635395 us; error 0 us; skew 500 ppm
I20260812 06:18:59.636257  9426 webserver.cc:533] Webserver started at http://127.9.52.129:43507/ using document root <none> and password file <none>
I20260812 06:18:59.636454  9426 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:59.636533  9426 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:59.636612  9426 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:59.637033  9426 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/instance:
uuid: "8839990a7e614ba1b4d37ee3ec4ef942"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-6ntk"
I20260812 06:18:59.638682  9426 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:18:59.639719  9850 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.639976  9426 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:59.640070  9426 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root
uuid: "8839990a7e614ba1b4d37ee3ec4ef942"
format_stamp: "Formatted at 2026-08-12 06:18:59 on dist-test-slave-6ntk"
I20260812 06:18:59.640157  9426 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:18:59.655838  9426 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:59.656294  9426 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:59.656636  9426 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:59.657135  9426 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:59.657200  9426 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.657269  9426 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:59.657320  9426 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:59.661775  9426 rpc_server.cc:307] RPC server started. Bound to: 127.9.52.129:34205
I20260812 06:18:59.662290  9941 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.9.52.129:34205 every 8 connection(s)
I20260812 06:18:59.670904  9943 heartbeater.cc:344] Connected to a master server at 127.9.52.190:35233
I20260812 06:18:59.671048  9943 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:59.671391  9943 heartbeater.cc:507] Master 127.9.52.190:35233 requested a full tablet report, sending...
I20260812 06:18:59.672158  9756 ts_manager.cc:194] Registered new tserver with Master: 8839990a7e614ba1b4d37ee3ec4ef942 (127.9.52.129:34205)
I20260812 06:18:59.672585  9426 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.010154962s
I20260812 06:18:59.673067  9756 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:49912
I20260812 06:18:59.680595  9756 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:49914:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:18:59.689565  9893 tablet_service.cc:1511] Processing CreateTablet for tablet b4e0360ea5fc402abf3d3fd3f35ec218 (DEFAULT_TABLE table=heavy-update-compaction-test [id=03ba1d8a61af4daa9facee47bf752d6b]), partition=
I20260812 06:18:59.689829  9893 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet b4e0360ea5fc402abf3d3fd3f35ec218. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:59.691951  9959 tablet_bootstrap.cc:492] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Bootstrap starting.
I20260812 06:18:59.692914  9959 tablet_bootstrap.cc:654] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:59.693994  9959 tablet_bootstrap.cc:492] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: No bootstrap required, opened a new log
I20260812 06:18:59.694067  9959 ts_tablet_manager.cc:1403] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:18:59.694458  9959 raft_consensus.cc:359] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8839990a7e614ba1b4d37ee3ec4ef942" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 34205 } }
I20260812 06:18:59.694545  9959 raft_consensus.cc:385] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:59.694567  9959 raft_consensus.cc:740] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 8839990a7e614ba1b4d37ee3ec4ef942, State: Initialized, Role: FOLLOWER
I20260812 06:18:59.694720  9959 consensus_queue.cc:260] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [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: "8839990a7e614ba1b4d37ee3ec4ef942" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 34205 } }
I20260812 06:18:59.694836  9959 raft_consensus.cc:399] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:59.694886  9959 raft_consensus.cc:493] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:59.694967  9959 raft_consensus.cc:3060] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:59.695879  9959 raft_consensus.cc:515] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8839990a7e614ba1b4d37ee3ec4ef942" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 34205 } }
I20260812 06:18:59.696007  9959 leader_election.cc:304] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [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: 8839990a7e614ba1b4d37ee3ec4ef942; no voters: 
I20260812 06:18:59.696157  9959 leader_election.cc:290] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:59.696297  9961 raft_consensus.cc:2804] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:59.696544  9959 ts_tablet_manager.cc:1434] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:59.696564  9961 raft_consensus.cc:697] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 1 LEADER]: Becoming Leader. State: Replica: 8839990a7e614ba1b4d37ee3ec4ef942, State: Running, Role: LEADER
I20260812 06:18:59.696555  9943 heartbeater.cc:499] Master 127.9.52.190:35233 was elected leader, sending a full tablet report...
I20260812 06:18:59.696764  9961 consensus_queue.cc:237] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [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: "8839990a7e614ba1b4d37ee3ec4ef942" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 34205 } }
I20260812 06:18:59.698084  9756 catalog_manager.cc:5719] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 reported cstate change: term changed from 0 to 1, leader changed from <none> to 8839990a7e614ba1b4d37ee3ec4ef942 (127.9.52.129). New cstate: current_term: 1 leader_uuid: "8839990a7e614ba1b4d37ee3ec4ef942" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "8839990a7e614ba1b4d37ee3ec4ef942" member_type: VOTER last_known_addr { host: "127.9.52.129" port: 34205 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:59.759722  9426 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.054s	user 0.022s	sys 0.000s
I20260812 06:18:59.913133  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=19.054940
I20260812 06:19:00.073592  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.160s	user 0.124s	sys 0.032s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":86,"dirs.run_cpu_time_us":230,"dirs.run_wall_time_us":917,"drs_written":1,"lbm_read_time_us":59,"lbm_reads_lt_1ms":4,"lbm_write_time_us":41506,"lbm_writes_lt_1ms":757,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"spinlock_wait_cycles":896,"update_count":1500}
I20260812 06:19:00.074411  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): free 20743880 bytes of WAL
I20260812 06:19:00.074724  9857 log_reader.cc:385] T b4e0360ea5fc402abf3d3fd3f35ec218: removed 2 log segments from log reader
I20260812 06:19:00.074791  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000001 (ops 1-6)
I20260812 06:19:00.074836  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000002 (ops 7-11)
I20260812 06:19:00.081169  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.007s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:19:00.081764  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:00.123723  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.042s	user 0.011s	sys 0.016s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.124356  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): 16411393 bytes on disk
I20260812 06:19:00.124939  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":88,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.125452  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:00.142397  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6271,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.143034  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:00.352377  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.209s	user 0.144s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774808,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":651,"lbm_read_time_us":15146,"lbm_reads_lt_1ms":569,"lbm_write_time_us":31450,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":359,"threads_started":5,"update_count":2500}
I20260812 06:19:00.353186  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:00.413245  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.060s	user 0.029s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":23836,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.413714  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:00.425408  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4227,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.426234  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:00.642532  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.216s	user 0.128s	sys 0.084s 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":379,"lbm_read_time_us":14379,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34084,"lbm_writes_lt_1ms":543,"mutex_wait_us":63,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":17792,"update_count":2500}
I20260812 06:19:00.643327  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:00.688376  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.045s	user 0.018s	sys 0.024s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19937,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.688953  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:00.704788  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.016s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5879,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.705381  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:00.869316  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.164s	user 0.129s	sys 0.028s 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":255,"lbm_read_time_us":11252,"lbm_reads_lt_1ms":572,"lbm_write_time_us":31140,"lbm_writes_lt_1ms":543,"mutex_wait_us":45,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2500}
I20260812 06:19:00.870111  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:00.926608  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.056s	user 0.025s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21061,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:00.927378  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:00.939672  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4348,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.940248  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:01.092262  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.152s	user 0.120s	sys 0.028s 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":517,"lbm_read_time_us":11831,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29762,"lbm_writes_lt_1ms":543,"mutex_wait_us":110,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10752,"update_count":2500}
I20260812 06:19:01.093019  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:01.148785  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.056s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23628,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.149326  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:01.160869  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4110,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.161346  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:01.335668  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.174s	user 0.129s	sys 0.031s 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":559,"lbm_read_time_us":13073,"lbm_reads_lt_1ms":572,"lbm_write_time_us":32356,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":2500}
I20260812 06:19:01.336428  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:01.388890  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.052s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20469,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.389376  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:01.401296  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.012s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4211,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.402009  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:01.432668  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.030s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":219,"dirs.run_wall_time_us":1456,"drs_written":1,"lbm_read_time_us":58,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2052,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:01.433495  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): free 124257239 bytes of WAL
I20260812 06:19:01.433808  9857 log_reader.cc:385] T b4e0360ea5fc402abf3d3fd3f35ec218: removed 12 log segments from log reader
I20260812 06:19:01.433902  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000003 (ops 12-16)
I20260812 06:19:01.433946  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000004 (ops 17-21)
I20260812 06:19:01.433982  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000005 (ops 22-26)
I20260812 06:19:01.434016  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000006 (ops 27-31)
I20260812 06:19:01.434046  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000007 (ops 32-36)
I20260812 06:19:01.434075  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000008 (ops 37-40)
I20260812 06:19:01.434104  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000009 (ops 41-45)
I20260812 06:19:01.434137  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000010 (ops 46-50)
I20260812 06:19:01.434171  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000011 (ops 51-55)
I20260812 06:19:01.434201  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000012 (ops 56-60)
I20260812 06:19:01.434230  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000013 (ops 61-65)
I20260812 06:19:01.434260  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000014 (ops 66-70)
I20260812 06:19:01.468004  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.034s	user 0.001s	sys 0.031s Metrics: {}
I20260812 06:19:01.468433  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:01.484027  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.015s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4767,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.484577  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): 472 bytes on disk
I20260812 06:19:01.485075  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:19:01.485563  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:01.496114  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3979,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.496578  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:01.700390  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.204s	user 0.159s	sys 0.044s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979749,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":997,"lbm_read_time_us":14650,"lbm_reads_lt_1ms":774,"lbm_write_time_us":44846,"lbm_writes_lt_1ms":743,"mutex_wait_us":414,"peak_mem_usage":87969044,"reinsert_count":0,"thread_start_us":88,"threads_started":1,"update_count":3500}
I20260812 06:19:01.703056  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:01.758234  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.055s	user 0.031s	sys 0.023s Metrics: {"bytes_written":16409905,"delete_count":0,"lbm_write_time_us":24667,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:01.758770  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:01.773125  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5250,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.773636  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:01.958155  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.184s	user 0.124s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774692,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1144,"lbm_read_time_us":13606,"lbm_reads_lt_1ms":572,"lbm_write_time_us":34111,"lbm_writes_lt_1ms":543,"mutex_wait_us":435,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":14464,"update_count":2500}
I20260812 06:19:01.958909  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:02.020792  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.062s	user 0.035s	sys 0.017s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":26416,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.021366  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:02.038712  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.017s	user 0.016s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6387,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.039410  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:02.237470  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.198s	user 0.109s	sys 0.075s 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":1659,"lbm_read_time_us":11681,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30616,"lbm_writes_lt_1ms":543,"mutex_wait_us":571,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":166784,"update_count":2500}
I20260812 06:19:02.238288  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:02.284972  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.046s	user 0.040s	sys 0.004s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":21222,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.285521  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:02.444613  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.159s	user 0.107s	sys 0.040s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672155,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":698,"lbm_read_time_us":10787,"lbm_reads_lt_1ms":467,"lbm_write_time_us":25771,"lbm_writes_lt_1ms":443,"mutex_wait_us":296,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:02.445338  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:02.500821  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.055s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":23784,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.501385  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:02.518644  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.017s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6672,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.519181  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:02.706055  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.187s	user 0.144s	sys 0.038s 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":108,"lbm_read_time_us":10634,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30949,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":11904,"update_count":2500}
I20260812 06:19:02.706825  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:02.767552  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.060s	user 0.030s	sys 0.029s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":25311,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:02.768314  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=3.181125
I20260812 06:19:02.784572  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":5120,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.785089  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:02.808563  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.023s	user 0.000s	sys 0.020s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3937,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.809293  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:03.034449  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.225s	user 0.144s	sys 0.075s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877206,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":11287,"lbm_read_time_us":15360,"lbm_reads_lt_1ms":673,"lbm_write_time_us":35332,"lbm_writes_lt_1ms":643,"mutex_wait_us":3720,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:19:03.035126  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=15.087375
I20260812 06:19:03.098255  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.063s	user 0.039s	sys 0.023s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":23101,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:03.098830  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.114243  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.015s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5224,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.114745  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.124752  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3824,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:03.125258  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:03.164824  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.039s	user 0.028s	sys 0.008s Metrics: {"bytes_written":1357580,"cfile_init":1,"dirs.queue_time_us":96,"dirs.run_cpu_time_us":310,"dirs.run_wall_time_us":1698,"drs_written":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2437,"lbm_writes_lt_1ms":44,"peak_mem_usage":0,"rows_written":33}
I20260812 06:19:03.165556  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): free 133477446 bytes of WAL
I20260812 06:19:03.165804  9857 log_reader.cc:385] T b4e0360ea5fc402abf3d3fd3f35ec218: removed 13 log segments from log reader
I20260812 06:19:03.165848  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000015 (ops 71-75)
I20260812 06:19:03.165962  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000016 (ops 76-80)
I20260812 06:19:03.166007  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000017 (ops 81-85)
I20260812 06:19:03.166026  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000018 (ops 86-90)
I20260812 06:19:03.166043  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000019 (ops 91-95)
I20260812 06:19:03.166103  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000020 (ops 96-100)
I20260812 06:19:03.166129  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000021 (ops 101-105)
I20260812 06:19:03.166175  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000022 (ops 106-110)
I20260812 06:19:03.166218  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000023 (ops 111-115)
I20260812 06:19:03.166258  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000024 (ops 116-120)
I20260812 06:19:03.166297  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000025 (ops 121-125)
I20260812 06:19:03.166337  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000026 (ops 126-130)
I20260812 06:19:03.166375  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000027 (ops 131-135)
I20260812 06:19:03.197745  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.032s	user 0.001s	sys 0.027s Metrics: {}
I20260812 06:19:03.198343  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.219583  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.021s	user 0.006s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6779,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.220173  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.231398  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.011s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4265,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.232185  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): 508 bytes on disk
I20260812 06:19:03.232811  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.233933  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:03.493753  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.260s	user 0.181s	sys 0.076s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37082267,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":1807,"lbm_read_time_us":18968,"lbm_reads_lt_1ms":875,"lbm_write_time_us":44270,"lbm_writes_lt_1ms":843,"mutex_wait_us":55,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":22400,"thread_start_us":86,"threads_started":1,"update_count":4000}
I20260812 06:19:03.494518  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=18.063937
I20260812 06:19:03.551213  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.057s	user 0.052s	sys 0.000s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":22975,"lbm_writes_lt_1ms":503,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2500}
I20260812 06:19:03.552031  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.571988  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.020s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5355,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.572474  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.584354  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.012s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4721,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.584878  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:03.777190  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.192s	user 0.156s	sys 0.036s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":32979633,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":182,"lbm_read_time_us":15672,"lbm_reads_lt_1ms":773,"lbm_write_time_us":37779,"lbm_writes_lt_1ms":743,"mutex_wait_us":29,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15360,"update_count":3500}
I20260812 06:19:03.778000  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=14.095187
I20260812 06:19:03.826182  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.048s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":21183,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.826805  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:03.846107  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.019s	user 0.012s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6407,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.846621  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.008416  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.162s	user 0.123s	sys 0.025s 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":1483,"lbm_read_time_us":10790,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28335,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":5120,"update_count":2500}
I20260812 06:19:04.009341  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=11.118625
I20260812 06:19:04.043193  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.034s	user 0.029s	sys 0.003s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":14787,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.043825  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.059976  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.016s	user 0.005s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5984,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.060734  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.204783  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.144s	user 0.091s	sys 0.052s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1193,"lbm_read_time_us":10368,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23634,"lbm_writes_lt_1ms":443,"mutex_wait_us":767,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:04.205552  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=10.126437
I20260812 06:19:04.257725  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.052s	user 0.024s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14491,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.258522  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.276083  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.017s	user 0.014s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6478,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.276798  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.454376  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.177s	user 0.118s	sys 0.059s 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":259,"lbm_read_time_us":12790,"lbm_reads_lt_1ms":472,"lbm_write_time_us":29739,"lbm_writes_lt_1ms":443,"mutex_wait_us":32,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":18176,"update_count":2000}
I20260812 06:19:04.455348  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=10.126437
I20260812 06:19:04.501030  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.045s	user 0.025s	sys 0.018s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18062,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.501567  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=3.181125
I20260812 06:19:04.520882  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.019s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4623,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.521425  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.532564  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4126,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.533229  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.695822  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.162s	user 0.132s	sys 0.030s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":566,"lbm_read_time_us":10804,"lbm_reads_lt_1ms":573,"lbm_write_time_us":33553,"lbm_writes_lt_1ms":543,"mutex_wait_us":58,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7040,"update_count":2500}
I20260812 06:19:04.696843  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=10.126437
I20260812 06:19:04.741405  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.044s	user 0.023s	sys 0.020s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":20018,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:04.742035  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.763862  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.019s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":5082,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:04.764484  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.774782  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3774459,"delete_count":0,"lbm_write_time_us":3734,"lbm_writes_lt_1ms":95,"reinsert_count":0,"update_count":460}
I20260812 06:19:04.775272  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.807726  9426 heavy-update-compaction-itest.cc:229] Time spent updating: real 5.048s	user 1.842s	sys 0.168s
I20260812 06:19:04.809698  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushMRSOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.034s	user 0.024s	sys 0.006s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":81,"dirs.run_cpu_time_us":268,"dirs.run_wall_time_us":1621,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1705,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:04.810495  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): free 132571590 bytes of WAL
I20260812 06:19:04.810793  9857 log_reader.cc:385] T b4e0360ea5fc402abf3d3fd3f35ec218: removed 13 log segments from log reader
I20260812 06:19:04.810863  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000028 (ops 136-140)
I20260812 06:19:04.810910  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000029 (ops 141-145)
I20260812 06:19:04.810941  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000030 (ops 146-150)
I20260812 06:19:04.810981  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000031 (ops 151-154)
I20260812 06:19:04.811009  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000032 (ops 155-159)
I20260812 06:19:04.811045  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000033 (ops 160-164)
I20260812 06:19:04.811082  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000034 (ops 165-169)
I20260812 06:19:04.811110  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000035 (ops 170-174)
I20260812 06:19:04.811146  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000036 (ops 175-179)
I20260812 06:19:04.811182  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000037 (ops 180-184)
I20260812 06:19:04.811272  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000038 (ops 185-188)
I20260812 06:19:04.811322  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000039 (ops 189-193)
I20260812 06:19:04.811362  9857 log.cc:1079] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: Deleting log segment in path: /tmp/dist-test-taskfgHzbG/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515533838149-9426-0/minicluster-data/ts-0-root/wals/b4e0360ea5fc402abf3d3fd3f35ec218/wal-000000040 (ops 194-198)
I20260812 06:19:04.845376  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: LogGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.035s	user 0.000s	sys 0.031s Metrics: {}
I20260812 06:19:04.845916  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218): 492 bytes on disk
I20260812 06:19:04.846534  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: UndoDeltaBlockGCOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.847172  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=2.188937
I20260812 06:19:04.857656  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: FlushDeltaMemStoresOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.858196  9944 maintenance_manager.cc:419] P 8839990a7e614ba1b4d37ee3ec4ef942: Scheduling MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218): perf score=1.000000
I20260812 06:19:04.878855  9426 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.071s	user 0.002s	sys 0.000s
I20260812 06:19:04.879421  9426 tablet_server.cc:179] TabletServer@127.9.52.129:0 shutting down...
I20260812 06:19:04.986127  9857 maintenance_manager.cc:643] P 8839990a7e614ba1b4d37ee3ec4ef942: MajorDeltaCompactionOp(b4e0360ea5fc402abf3d3fd3f35ec218) complete. Timing: real 0.128s	user 0.088s	sys 0.039s Metrics: {"cfile_cache_hit":527,"cfile_cache_hit_bytes":23922323,"cfile_cache_miss":107,"cfile_cache_miss_bytes":4955008,"cfile_init":4,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":476,"lbm_read_time_us":2162,"lbm_reads_lt_1ms":123,"lbm_write_time_us":30598,"lbm_writes_lt_1ms":643,"mutex_wait_us":55,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1280,"thread_start_us":87,"threads_started":1,"update_count":3000}
I20260812 06:19:04.986954  9426 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:04.987241  9426 tablet_replica.cc:333] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942: stopping tablet replica
I20260812 06:19:04.987440  9426 raft_consensus.cc:2243] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:04.987653  9426 raft_consensus.cc:2272] T b4e0360ea5fc402abf3d3fd3f35ec218 P 8839990a7e614ba1b4d37ee3ec4ef942 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.002074  9426 tablet_server.cc:196] TabletServer@127.9.52.129:0 shutdown complete.
I20260812 06:19:05.038512  9426 master.cc:562] Master@127.9.52.190:35233 shutting down...
I20260812 06:19:05.042858  9426 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:05.043120  9426 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:05.043219  9426 tablet_replica.cc:333] T 00000000000000000000000000000000 P 7cfe6d63c8ec4267b76c211a1c3de722: stopping tablet replica
I20260812 06:19:05.056149  9426 master.cc:584] Master@127.9.52.190:35233 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5597 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (11301 ms total)

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