[==========] 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:57.821002 23517 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.247.126:34959
I20260812 06:18:57.821903 23517 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:57.822458 23517 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.827863 23523 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:57.827991 23533 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:57.828037 23517 server_base.cc:1061] running on GCE node
W20260812 06:18:57.828119 23527 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:57.828569 23517 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.828650 23517 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:57.828678 23517 hybrid_clock.cc:648] HybridClock initialized: now 1786515537828676 us; error 0 us; skew 500 ppm
I20260812 06:18:57.830245 23517 webserver.cc:533] Webserver started at http://127.22.247.126:34743/ using document root <none> and password file <none>
I20260812 06:18:57.830747 23517 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.830802 23517 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.831014 23517 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.832613 23517 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/master-0-root/instance:
uuid: "0c4c231c58bb406ca1d4decacd0cbe83"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-6zbq"
I20260812 06:18:57.835727 23517 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.005s	sys 0.000s
I20260812 06:18:57.837481 23548 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:57.838397 23517 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:18:57.838498 23517 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/master-0-root
uuid: "0c4c231c58bb406ca1d4decacd0cbe83"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-6zbq"
I20260812 06:18:57.838579 23517 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-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:57.853636 23517 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.854104 23517 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:57.854241 23517 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.860786 23517 rpc_server.cc:307] RPC server started. Bound to: 127.22.247.126:34959
I20260812 06:18:57.860795 23641 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.247.126:34959 every 8 connection(s)
I20260812 06:18:57.862735 23645 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:57.867421 23645 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: Bootstrap starting.
I20260812 06:18:57.869496 23645 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.870270 23645 log.cc:826] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: Log is configured to *not* fsync() on all Append() calls
I20260812 06:18:57.871676 23645 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: No bootstrap required, opened a new log
I20260812 06:18:57.874161 23645 raft_consensus.cc:359] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER }
I20260812 06:18:57.874301 23645 raft_consensus.cc:385] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.874378 23645 raft_consensus.cc:740] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 0c4c231c58bb406ca1d4decacd0cbe83, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.874889 23645 consensus_queue.cc:260] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [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: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER }
I20260812 06:18:57.875087 23645 raft_consensus.cc:399] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.875151 23645 raft_consensus.cc:493] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.875264 23645 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.876117 23645 raft_consensus.cc:515] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER }
I20260812 06:18:57.876500 23645 leader_election.cc:304] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [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: 0c4c231c58bb406ca1d4decacd0cbe83; no voters: 
I20260812 06:18:57.876806 23645 leader_election.cc:290] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.876974 23652 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.877185 23652 raft_consensus.cc:697] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 1 LEADER]: Becoming Leader. State: Replica: 0c4c231c58bb406ca1d4decacd0cbe83, State: Running, Role: LEADER
I20260812 06:18:57.877593 23652 consensus_queue.cc:237] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [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: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER }
I20260812 06:18:57.877691 23645 sys_catalog.cc:565] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:18:57.878965 23653 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 0c4c231c58bb406ca1d4decacd0cbe83. Latest consensus state: current_term: 1 leader_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER } }
I20260812 06:18:57.879055 23653 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.879405 23673 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:18:57.879369 23656 sys_catalog.cc:455] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "0c4c231c58bb406ca1d4decacd0cbe83" member_type: VOTER } }
I20260812 06:18:57.879510 23656 sys_catalog.cc:458] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [sys.catalog]: This master's current role is: LEADER
I20260812 06:18:57.879833 23517 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:18:57.881714 23673 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:18:57.885542 23673 catalog_manager.cc:1383] Generated new cluster ID: 15d0f8cd8ab6476eb41da0a27c3cb21d
I20260812 06:18:57.885597 23673 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:18:57.896032 23673 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:18:57.896986 23673 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:18:57.903230 23673 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: Generated new TSK 0
I20260812 06:18:57.903776 23673 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:18:57.912184 23517 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:18:57.914618 23694 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:57.914655 23701 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:57.914788 23693 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:57.914882 23517 server_base.cc:1061] running on GCE node
I20260812 06:18:57.915014 23517 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:18:57.915048 23517 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:57.915068 23517 hybrid_clock.cc:648] HybridClock initialized: now 1786515537915068 us; error 0 us; skew 500 ppm
I20260812 06:18:57.915854 23517 webserver.cc:533] Webserver started at http://127.22.247.65:33421/ using document root <none> and password file <none>
I20260812 06:18:57.916002 23517 fs_manager.cc:362] Metadata directory not provided
I20260812 06:18:57.916046 23517 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:18:57.916112 23517 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:18:57.916419 23517 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/instance:
uuid: "e13c091f7c4442ac88a3a5c25646b629"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-6zbq"
I20260812 06:18:57.917718 23517 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.001s
I20260812 06:18:57.918601 23716 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:57.918856 23517 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:18:57.918923 23517 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root
uuid: "e13c091f7c4442ac88a3a5c25646b629"
format_stamp: "Formatted at 2026-08-12 06:18:57 on dist-test-slave-6zbq"
I20260812 06:18:57.918984 23517 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-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:57.928892 23517 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:18:57.929241 23517 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:18:57.929611 23517 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:18:57.930328 23517 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:18:57.930410 23517 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.930455 23517 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:18:57.930486 23517 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:18:57.936228 23517 rpc_server.cc:307] RPC server started. Bound to: 127.22.247.65:34493
I20260812 06:18:57.936254 23837 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.247.65:34493 every 8 connection(s)
I20260812 06:18:57.948446 23839 heartbeater.cc:344] Connected to a master server at 127.22.247.126:34959
I20260812 06:18:57.948652 23839 heartbeater.cc:461] Registering TS with master...
I20260812 06:18:57.949023 23839 heartbeater.cc:507] Master 127.22.247.126:34959 requested a full tablet report, sending...
I20260812 06:18:57.950248 23587 ts_manager.cc:194] Registered new tserver with Master: e13c091f7c4442ac88a3a5c25646b629 (127.22.247.65:34493)
I20260812 06:18:57.951068 23517 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014309983s
I20260812 06:18:57.951467 23587 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:42548
I20260812 06:18:57.959278 23587 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:42562:
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:57.972648 23767 tablet_service.cc:1511] Processing CreateTablet for tablet 15bdd7e2963d40f9a63a6d436ea58ae0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=54e922747b8a40f4bd1617db07abf105]), partition=
I20260812 06:18:57.972985 23767 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 15bdd7e2963d40f9a63a6d436ea58ae0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:18:57.974938 23864 tablet_bootstrap.cc:492] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Bootstrap starting.
I20260812 06:18:57.975893 23864 tablet_bootstrap.cc:654] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Neither blocks nor log segments found. Creating new log.
I20260812 06:18:57.976840 23864 tablet_bootstrap.cc:492] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: No bootstrap required, opened a new log
I20260812 06:18:57.976919 23864 ts_tablet_manager.cc:1403] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:18:57.977305 23864 raft_consensus.cc:359] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e13c091f7c4442ac88a3a5c25646b629" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 34493 } }
I20260812 06:18:57.977391 23864 raft_consensus.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:18:57.977421 23864 raft_consensus.cc:740] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e13c091f7c4442ac88a3a5c25646b629, State: Initialized, Role: FOLLOWER
I20260812 06:18:57.977545 23864 consensus_queue.cc:260] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [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: "e13c091f7c4442ac88a3a5c25646b629" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 34493 } }
I20260812 06:18:57.977627 23864 raft_consensus.cc:399] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:18:57.977664 23864 raft_consensus.cc:493] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:18:57.977711 23864 raft_consensus.cc:3060] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:18:57.978410 23864 raft_consensus.cc:515] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e13c091f7c4442ac88a3a5c25646b629" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 34493 } }
I20260812 06:18:57.978528 23864 leader_election.cc:304] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [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: e13c091f7c4442ac88a3a5c25646b629; no voters: 
I20260812 06:18:57.978703 23864 leader_election.cc:290] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:18:57.978808 23870 raft_consensus.cc:2804] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:18:57.978973 23870 raft_consensus.cc:697] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 1 LEADER]: Becoming Leader. State: Replica: e13c091f7c4442ac88a3a5c25646b629, State: Running, Role: LEADER
I20260812 06:18:57.979014 23864 ts_tablet_manager.cc:1434] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:18:57.979389 23839 heartbeater.cc:499] Master 127.22.247.126:34959 was elected leader, sending a full tablet report...
I20260812 06:18:57.979542 23870 consensus_queue.cc:237] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [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: "e13c091f7c4442ac88a3a5c25646b629" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 34493 } }
I20260812 06:18:57.982013 23587 catalog_manager.cc:5719] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 reported cstate change: term changed from 0 to 1, leader changed from <none> to e13c091f7c4442ac88a3a5c25646b629 (127.22.247.65). New cstate: current_term: 1 leader_uuid: "e13c091f7c4442ac88a3a5c25646b629" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e13c091f7c4442ac88a3a5c25646b629" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 34493 } health_report { overall_health: HEALTHY } } }
I20260812 06:18:58.038906 23517 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.012s	sys 0.011s
I20260812 06:18:58.187251 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=23.023690
I20260812 06:18:58.367558 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.180s	user 0.137s	sys 0.035s Metrics: {"bytes_written":12307490,"cfile_init":1,"compiler_manager_pool.queue_time_us":62932,"compiler_manager_pool.run_cpu_time_us":174429,"compiler_manager_pool.run_wall_time_us":179074,"delete_count":0,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":192,"dirs.run_wall_time_us":760,"drs_written":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45320,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":113,"threads_started":1,"update_count":1500}
I20260812 06:18:58.368494 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): free 20743880 bytes of WAL
I20260812 06:18:58.368765 23722 log_reader.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0: removed 2 log segments from log reader
I20260812 06:18:58.368818 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000001 (ops 1-6)
I20260812 06:18:58.368860 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000002 (ops 7-11)
I20260812 06:18:58.372387 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.004s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:18:58.372665 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): 20513813 bytes on disk
I20260812 06:18:58.373126 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":50,"lbm_reads_lt_1ms":4}
I20260812 06:18:58.373471 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:58.384425 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3894,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.384867 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:58.520171 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.135s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":429,"lbm_read_time_us":9138,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20176,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"thread_start_us":284,"threads_started":5,"update_count":2000}
I20260812 06:18:58.520812 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:58.565496 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.045s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307494,"delete_count":0,"lbm_write_time_us":13525,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.565922 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:58.575634 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3711,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.576162 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:58.700556 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.124s	user 0.092s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713276,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":9217,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23063,"lbm_writes_lt_1ms":443,"mutex_wait_us":29,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9472,"update_count":2000}
I20260812 06:18:58.700974 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:58.739195 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.038s	user 0.027s	sys 0.004s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13538,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.739710 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:58.750533 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3886,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.750957 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:58.867450 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.116s	user 0.092s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":550,"lbm_read_time_us":8718,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22228,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9984,"update_count":2000}
I20260812 06:18:58.867864 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:58.910691 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.043s	user 0.024s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13903,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:58.911175 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:58.920499 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3551,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:58.920908 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.060006 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.139s	user 0.107s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":9411,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23534,"lbm_writes_lt_1ms":443,"mutex_wait_us":17,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":2000}
I20260812 06:18:59.060751 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:59.097777 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.037s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12652,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.098258 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.107802 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3591,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.108197 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.217093 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.109s	user 0.084s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":7259,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20972,"lbm_writes_lt_1ms":443,"mutex_wait_us":43,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":107264,"update_count":2000}
I20260812 06:18:59.217517 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:59.255213 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.038s	user 0.018s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13457,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.255662 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.264932 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3585,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.265316 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.384245 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.119s	user 0.094s	sys 0.025s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":129,"lbm_read_time_us":9347,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22246,"lbm_writes_lt_1ms":443,"mutex_wait_us":34,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2000}
I20260812 06:18:59.384828 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:18:59.423957 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.039s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14080,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:18:59.424474 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.438833 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.014s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5452,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.439314 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.466014 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.026s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":77,"dirs.run_cpu_time_us":175,"dirs.run_wall_time_us":1061,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1705,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:18:59.466817 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): free 120553372 bytes of WAL
I20260812 06:18:59.467041 23722 log_reader.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0: removed 12 log segments from log reader
I20260812 06:18:59.467100 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000003 (ops 12-16)
I20260812 06:18:59.467146 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000004 (ops 17-21)
I20260812 06:18:59.467180 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000005 (ops 22-26)
I20260812 06:18:59.467203 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000006 (ops 27-31)
I20260812 06:18:59.467231 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000007 (ops 32-36)
I20260812 06:18:59.467258 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000008 (ops 37-40)
I20260812 06:18:59.467288 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000009 (ops 41-45)
I20260812 06:18:59.467319 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000010 (ops 46-50)
I20260812 06:18:59.467348 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000011 (ops 51-54)
I20260812 06:18:59.467375 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000012 (ops 55-59)
I20260812 06:18:59.467402 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000013 (ops 60-64)
I20260812 06:18:59.467433 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000014 (ops 65-69)
I20260812 06:18:59.494047 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.027s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:18:59.494449 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): 447 bytes on disk
I20260812 06:18:59.495007 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:18:59.495460 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=3.181125
I20260812 06:18:59.511714 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.016s	user 0.010s	sys 0.005s Metrics: {"bytes_written":4882122,"delete_count":0,"lbm_write_time_us":6313,"lbm_writes_lt_1ms":122,"reinsert_count":0,"update_count":595}
I20260812 06:18:59.512058 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.520975 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.003s	sys 0.003s Metrics: {"bytes_written":3323180,"delete_count":0,"lbm_write_time_us":2836,"lbm_writes_lt_1ms":84,"reinsert_count":0,"update_count":405}
I20260812 06:18:59.521374 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.683116 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.162s	user 0.134s	sys 0.024s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918318,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":260,"lbm_read_time_us":11821,"lbm_reads_lt_1ms":674,"lbm_write_time_us":30689,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":1792,"thread_start_us":71,"threads_started":1,"update_count":3000}
I20260812 06:18:59.683615 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=14.095187
I20260812 06:18:59.723646 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.040s	user 0.020s	sys 0.016s Metrics: {"bytes_written":16409907,"delete_count":0,"lbm_write_time_us":16175,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:18:59.724134 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.737356 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5295,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:18:59.737720 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:18:59.882822 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.145s	user 0.101s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1024,"lbm_read_time_us":10427,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26550,"lbm_writes_lt_1ms":543,"mutex_wait_us":272,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3328,"update_count":2500}
I20260812 06:18:59.883695 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=11.118625
I20260812 06:18:59.910414 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.026s	user 0.006s	sys 0.020s Metrics: {"bytes_written":12717739,"delete_count":0,"lbm_write_time_us":11595,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:18:59.910862 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:18:59.924119 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.013s	user 0.005s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3570,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:18:59.924568 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.060184 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.135s	user 0.092s	sys 0.042s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713267,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":553,"lbm_read_time_us":9643,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21913,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:00.060710 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=11.118625
I20260812 06:19:00.093182 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.032s	user 0.016s	sys 0.013s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13830,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:00.093710 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:00.108011 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5368,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:00.108405 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.225929 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.117s	user 0.083s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":611,"lbm_read_time_us":7654,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20430,"lbm_writes_lt_1ms":443,"mutex_wait_us":312,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2000}
I20260812 06:19:00.226429 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:00.264875 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.038s	user 0.018s	sys 0.017s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":17432,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.265400 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:00.279091 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.014s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5087,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.279577 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.410912 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.131s	user 0.115s	sys 0.015s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":566,"lbm_read_time_us":9706,"lbm_reads_lt_1ms":472,"lbm_write_time_us":25014,"lbm_writes_lt_1ms":443,"mutex_wait_us":46,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":2000}
I20260812 06:19:00.411369 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:00.449290 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.038s	user 0.022s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15788,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.449764 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:00.458983 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3637,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.459473 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.578233 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.118s	user 0.098s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":413,"lbm_read_time_us":8030,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23102,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:00.578907 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:00.617749 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.039s	user 0.022s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13382,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.618209 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:00.632917 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.015s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5807,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.634130 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.764365 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.130s	user 0.086s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":439,"lbm_read_time_us":9908,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20984,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:00.764936 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:00.793483 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.028s	user 0.013s	sys 0.012s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12368,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:00.794425 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:00.809762 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5796,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:00.810441 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:00.841463 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316419,"cfile_init":1,"dirs.queue_time_us":53,"dirs.run_cpu_time_us":193,"dirs.run_wall_time_us":1137,"drs_written":1,"lbm_read_time_us":40,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1527,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:00.842204 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): free 124710310 bytes of WAL
I20260812 06:19:00.842473 23722 log_reader.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0: removed 12 log segments from log reader
I20260812 06:19:00.842520 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000015 (ops 70-74)
I20260812 06:19:00.842558 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000016 (ops 75-79)
I20260812 06:19:00.842592 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000017 (ops 80-84)
I20260812 06:19:00.842623 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000018 (ops 85-89)
I20260812 06:19:00.842654 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000019 (ops 90-94)
I20260812 06:19:00.842693 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000020 (ops 95-99)
I20260812 06:19:00.842724 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000021 (ops 100-104)
I20260812 06:19:00.842784 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000022 (ops 105-109)
I20260812 06:19:00.842820 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000023 (ops 110-114)
I20260812 06:19:00.842842 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000024 (ops 115-119)
I20260812 06:19:00.842860 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000025 (ops 120-124)
I20260812 06:19:00.842875 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000026 (ops 125-129)
I20260812 06:19:00.867203 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:00.867556 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): 493 bytes on disk
I20260812 06:19:00.868223 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":67,"lbm_reads_lt_1ms":4}
I20260812 06:19:00.868818 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=6.157687
I20260812 06:19:00.892987 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.024s	user 0.010s	sys 0.011s Metrics: {"bytes_written":8164054,"delete_count":0,"lbm_write_time_us":7708,"lbm_writes_lt_1ms":202,"reinsert_count":0,"update_count":995}
I20260812 06:19:00.893440 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:01.072068 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.178s	user 0.100s	sys 0.076s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28877194,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":2215,"lbm_read_time_us":12753,"lbm_reads_lt_1ms":668,"lbm_write_time_us":30002,"lbm_writes_lt_1ms":642,"mutex_wait_us":1561,"peak_mem_usage":75501437,"reinsert_count":0,"spinlock_wait_cycles":9344,"thread_start_us":68,"threads_started":1,"update_count":2995}
I20260812 06:19:01.072588 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=14.095187
I20260812 06:19:01.121613 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.049s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16450930,"delete_count":0,"lbm_write_time_us":17143,"lbm_writes_lt_1ms":404,"reinsert_count":0,"update_count":2005}
I20260812 06:19:01.122074 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): free 12017954 bytes of WAL
I20260812 06:19:01.122305 23722 log_reader.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0: removed 1 log segments from log reader
I20260812 06:19:01.122381 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000027 (ops 130-134)
I20260812 06:19:01.124361 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:19:01.124691 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:01.133999 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3599,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.134403 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:01.304692 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.170s	user 0.106s	sys 0.055s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24856712,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":114,"lbm_read_time_us":11820,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27902,"lbm_writes_lt_1ms":544,"mutex_wait_us":24,"peak_mem_usage":63156935,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2505}
I20260812 06:19:01.305222 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=14.095187
I20260812 06:19:01.351562 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.046s	user 0.023s	sys 0.020s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19647,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:01.352064 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:01.368641 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.016s	user 0.004s	sys 0.010s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3895,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.369027 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:01.525133 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.156s	user 0.096s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":206,"lbm_read_time_us":11752,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25837,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":38528,"update_count":2500}
I20260812 06:19:01.525626 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=11.118625
I20260812 06:19:01.557950 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.032s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":13394,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:01.558473 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:01.571378 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.013s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4510,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:01.571954 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:01.691452 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.119s	user 0.106s	sys 0.012s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":436,"lbm_read_time_us":7947,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22213,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:01.692054 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:01.728127 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.036s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":15412,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.728618 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:01.740711 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.012s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4444,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.741165 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:01.851706 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.110s	user 0.090s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":347,"lbm_read_time_us":7623,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21670,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1152,"update_count":2000}
I20260812 06:19:01.852682 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:01.889117 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.036s	user 0.028s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13601,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:01.889858 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:01.899780 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3800,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:01.900164 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:02.012346 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.112s	user 0.090s	sys 0.020s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":328,"lbm_read_time_us":7835,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20810,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2000}
I20260812 06:19:02.012859 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:02.059755 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.047s	user 0.030s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16920,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.060290 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:02.069743 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3629,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.070199 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:02.205973 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.136s	user 0.088s	sys 0.044s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":804,"lbm_read_time_us":10107,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20940,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2000}
I20260812 06:19:02.206465 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=10.126437
I20260812 06:19:02.247782 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.041s	user 0.023s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15834,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:02.248267 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:02.257723 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3752,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:02.258239 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:02.286319 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushMRSOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.028s	user 0.026s	sys 0.001s Metrics: {"bytes_written":1275447,"cfile_init":1,"dirs.queue_time_us":66,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1107,"drs_written":1,"lbm_read_time_us":41,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1673,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:19:02.287014 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): free 121459753 bytes of WAL
I20260812 06:19:02.287226 23722 log_reader.cc:385] T 15bdd7e2963d40f9a63a6d436ea58ae0: removed 12 log segments from log reader
I20260812 06:19:02.287268 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000028 (ops 135-139)
I20260812 06:19:02.287305 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000029 (ops 140-144)
I20260812 06:19:02.287335 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000030 (ops 145-149)
I20260812 06:19:02.287377 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000031 (ops 150-154)
I20260812 06:19:02.287413 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000032 (ops 155-159)
I20260812 06:19:02.287437 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000033 (ops 160-164)
I20260812 06:19:02.287459 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000034 (ops 165-169)
I20260812 06:19:02.287482 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000035 (ops 170-174)
I20260812 06:19:02.287513 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000036 (ops 175-179)
I20260812 06:19:02.287537 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000037 (ops 180-184)
I20260812 06:19:02.287569 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000038 (ops 185-189)
I20260812 06:19:02.287601 23722 log.cc:1079] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/15bdd7e2963d40f9a63a6d436ea58ae0/wal-000000039 (ops 190-194)
I20260812 06:19:02.311391 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: LogGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:02.311908 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=3.181125
I20260812 06:19:02.322836 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.011s	user 0.005s	sys 0.006s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":3972,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:02.323252 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0): 481 bytes on disk
I20260812 06:19:02.323637 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: UndoDeltaBlockGCOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4}
I20260812 06:19:02.324190 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=2.188937
I20260812 06:19:02.340386 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3293,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:02.340792 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=1.000000
I20260812 06:19:02.432000 23517 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.393s	user 1.643s	sys 0.086s
I20260812 06:19:02.539922 23517 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.107s	user 0.003s	sys 0.000s
I20260812 06:19:02.540555 23517 tablet_server.cc:179] TabletServer@127.22.247.65:0 shutting down...
I20260812 06:19:02.543980 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: MajorDeltaCompactionOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.203s	user 0.126s	sys 0.073s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918320,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":724,"lbm_read_time_us":12916,"lbm_reads_lt_1ms":670,"lbm_write_time_us":34352,"lbm_writes_lt_1ms":643,"mutex_wait_us":286,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8192,"thread_start_us":72,"threads_started":1,"update_count":3000}
I20260812 06:19:02.544574 23842 maintenance_manager.cc:419] P e13c091f7c4442ac88a3a5c25646b629: Scheduling FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0): perf score=6.157687
I20260812 06:19:02.569473 23722 maintenance_manager.cc:643] P e13c091f7c4442ac88a3a5c25646b629: FlushDeltaMemStoresOp(15bdd7e2963d40f9a63a6d436ea58ae0) complete. Timing: real 0.025s	user 0.014s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":10279,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:02.569972 23517 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:02.570318 23517 tablet_replica.cc:333] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629: stopping tablet replica
I20260812 06:19:02.570565 23517 raft_consensus.cc:2243] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.570832 23517 raft_consensus.cc:2272] T 15bdd7e2963d40f9a63a6d436ea58ae0 P e13c091f7c4442ac88a3a5c25646b629 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.585893 23517 tablet_server.cc:196] TabletServer@127.22.247.65:0 shutdown complete.
I20260812 06:19:02.594017 23517 master.cc:562] Master@127.22.247.126:34959 shutting down...
I20260812 06:19:02.598048 23517 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:02.598196 23517 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:02.598263 23517 tablet_replica.cc:333] T 00000000000000000000000000000000 P 0c4c231c58bb406ca1d4decacd0cbe83: stopping tablet replica
I20260812 06:19:02.784113 23517 master.cc:584] Master@127.22.247.126:34959 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5036 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:02.868664 23517 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.22.247.126:40747
I20260812 06:19:02.868971 23517 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.870658 23904 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.870844 23517 server_base.cc:1061] running on GCE node
W20260812 06:19:02.870831 23910 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.870893 23905 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.871186 23517 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.871229 23517 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.871244 23517 hybrid_clock.cc:648] HybridClock initialized: now 1786515542871244 us; error 0 us; skew 500 ppm
I20260812 06:19:02.871984 23517 webserver.cc:533] Webserver started at http://127.22.247.126:33593/ using document root <none> and password file <none>
I20260812 06:19:02.872104 23517 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.872143 23517 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.872190 23517 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.872516 23517 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/master-0-root/instance:
uuid: "dae59b26f5344fb085f11220023e0ea7"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-6zbq"
I20260812 06:19:02.873910 23517 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:02.875332 23923 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.875591 23517 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.000s
I20260812 06:19:02.875669 23517 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/master-0-root
uuid: "dae59b26f5344fb085f11220023e0ea7"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-6zbq"
I20260812 06:19:02.875751 23517 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.885763 23517 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.886117 23517 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.889889 23517 rpc_server.cc:307] RPC server started. Bound to: 127.22.247.126:40747
I20260812 06:19:02.894721 24011 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.247.126:40747 every 8 connection(s)
I20260812 06:19:02.895148 24014 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.896809 24014 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7: Bootstrap starting.
I20260812 06:19:02.897539 24014 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.898499 24014 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7: No bootstrap required, opened a new log
I20260812 06:19:02.898867 24014 raft_consensus.cc:359] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER }
I20260812 06:19:02.898947 24014 raft_consensus.cc:385] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.898978 24014 raft_consensus.cc:740] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: dae59b26f5344fb085f11220023e0ea7, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.899111 24014 consensus_queue.cc:260] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [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: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER }
I20260812 06:19:02.899186 24014 raft_consensus.cc:399] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.899226 24014 raft_consensus.cc:493] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.899276 24014 raft_consensus.cc:3060] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.899895 24014 raft_consensus.cc:515] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER }
I20260812 06:19:02.900010 24014 leader_election.cc:304] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [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: dae59b26f5344fb085f11220023e0ea7; no voters: 
I20260812 06:19:02.900197 24014 leader_election.cc:290] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.900316 24018 raft_consensus.cc:2804] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.900507 24018 raft_consensus.cc:697] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 1 LEADER]: Becoming Leader. State: Replica: dae59b26f5344fb085f11220023e0ea7, State: Running, Role: LEADER
I20260812 06:19:02.900604 24014 sys_catalog.cc:565] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:02.900637 24018 consensus_queue.cc:237] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [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: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER }
I20260812 06:19:02.901049 24019 sys_catalog.cc:455] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "dae59b26f5344fb085f11220023e0ea7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER } }
I20260812 06:19:02.901161 24019 sys_catalog.cc:458] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.901095 24021 sys_catalog.cc:455] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [sys.catalog]: SysCatalogTable state changed. Reason: New leader dae59b26f5344fb085f11220023e0ea7. Latest consensus state: current_term: 1 leader_uuid: "dae59b26f5344fb085f11220023e0ea7" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "dae59b26f5344fb085f11220023e0ea7" member_type: VOTER } }
I20260812 06:19:02.901216 24021 sys_catalog.cc:458] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:02.901468 24026 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:02.902395 24026 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:02.902585 23517 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:02.904089 24026 catalog_manager.cc:1383] Generated new cluster ID: 38dcfe7c72744939b9201a5fddb4902b
I20260812 06:19:02.904146 24026 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:02.914322 24026 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:02.914819 24026 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:02.919802 24026 catalog_manager.cc:6092] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7: Generated new TSK 0
I20260812 06:19:02.919950 24026 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:02.934679 23517 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:02.936264 24057 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.936308 24060 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:02.936343 24051 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:02.936437 23517 server_base.cc:1061] running on GCE node
I20260812 06:19:02.936685 23517 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:02.936730 23517 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:02.936745 23517 hybrid_clock.cc:648] HybridClock initialized: now 1786515542936745 us; error 0 us; skew 500 ppm
I20260812 06:19:02.937469 23517 webserver.cc:533] Webserver started at http://127.22.247.65:35553/ using document root <none> and password file <none>
I20260812 06:19:02.937605 23517 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:02.937649 23517 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:02.937737 23517 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:02.938057 23517 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/instance:
uuid: "77df7980567a4b52834713568b280898"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-6zbq"
I20260812 06:19:02.939438 23517 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:02.940270 24070 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.940485 23517 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:02.940547 23517 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root
uuid: "77df7980567a4b52834713568b280898"
format_stamp: "Formatted at 2026-08-12 06:19:02 on dist-test-slave-6zbq"
I20260812 06:19:02.940610 23517 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:02.950870 23517 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:02.951146 23517 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:02.951382 23517 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:02.951776 23517 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:02.951812 23517 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.951844 23517 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:02.951872 23517 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:02.955621 23517 rpc_server.cc:307] RPC server started. Bound to: 127.22.247.65:40115
I20260812 06:19:02.955642 24177 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.22.247.65:40115 every 8 connection(s)
I20260812 06:19:02.964255 24179 heartbeater.cc:344] Connected to a master server at 127.22.247.126:40747
I20260812 06:19:02.964341 24179 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:02.964514 24179 heartbeater.cc:507] Master 127.22.247.126:40747 requested a full tablet report, sending...
I20260812 06:19:02.965077 23952 ts_manager.cc:194] Registered new tserver with Master: 77df7980567a4b52834713568b280898 (127.22.247.65:40115)
I20260812 06:19:02.965739 23952 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:46434
I20260812 06:19:02.965849 23517 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009868516s
I20260812 06:19:02.971993 23952 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:46442:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:02.979697 24121 tablet_service.cc:1511] Processing CreateTablet for tablet 75e1c701bf1543929599aafe4a81ed8d (DEFAULT_TABLE table=heavy-update-compaction-test [id=38515684652649b5bc3509edc4d0e440]), partition=
I20260812 06:19:02.979919 24121 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 75e1c701bf1543929599aafe4a81ed8d. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:02.981598 24194 tablet_bootstrap.cc:492] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Bootstrap starting.
I20260812 06:19:02.982616 24194 tablet_bootstrap.cc:654] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:02.983561 24194 tablet_bootstrap.cc:492] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: No bootstrap required, opened a new log
I20260812 06:19:02.983633 24194 ts_tablet_manager.cc:1403] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.983990 24194 raft_consensus.cc:359] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77df7980567a4b52834713568b280898" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 40115 } }
I20260812 06:19:02.984067 24194 raft_consensus.cc:385] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:02.984099 24194 raft_consensus.cc:740] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 77df7980567a4b52834713568b280898, State: Initialized, Role: FOLLOWER
I20260812 06:19:02.984238 24194 consensus_queue.cc:260] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [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: "77df7980567a4b52834713568b280898" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 40115 } }
I20260812 06:19:02.984308 24194 raft_consensus.cc:399] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:02.984340 24194 raft_consensus.cc:493] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:02.984387 24194 raft_consensus.cc:3060] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:02.985047 24194 raft_consensus.cc:515] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77df7980567a4b52834713568b280898" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 40115 } }
I20260812 06:19:02.985183 24194 leader_election.cc:304] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [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: 77df7980567a4b52834713568b280898; no voters: 
I20260812 06:19:02.985368 24194 leader_election.cc:290] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:02.985474 24196 raft_consensus.cc:2804] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:02.985685 24194 ts_tablet_manager.cc:1434] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:02.985705 24196 raft_consensus.cc:697] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 1 LEADER]: Becoming Leader. State: Replica: 77df7980567a4b52834713568b280898, State: Running, Role: LEADER
I20260812 06:19:02.985800 24179 heartbeater.cc:499] Master 127.22.247.126:40747 was elected leader, sending a full tablet report...
I20260812 06:19:02.985821 24196 consensus_queue.cc:237] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [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: "77df7980567a4b52834713568b280898" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 40115 } }
I20260812 06:19:02.986996 23952 catalog_manager.cc:5719] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 reported cstate change: term changed from 0 to 1, leader changed from <none> to 77df7980567a4b52834713568b280898 (127.22.247.65). New cstate: current_term: 1 leader_uuid: "77df7980567a4b52834713568b280898" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "77df7980567a4b52834713568b280898" member_type: VOTER last_known_addr { host: "127.22.247.65" port: 40115 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:03.037726 23517 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.047s	user 0.012s	sys 0.008s
I20260812 06:19:03.206444 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d): perf score=23.023690
I20260812 06:19:03.372527 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.166s	user 0.121s	sys 0.037s Metrics: {"bytes_written":15999661,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":786,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46528,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"spinlock_wait_cycles":1280,"update_count":1950}
I20260812 06:19:03.373121 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling LogGCOp(75e1c701bf1543929599aafe4a81ed8d): free 32761802 bytes of WAL
I20260812 06:19:03.373344 24080 log_reader.cc:385] T 75e1c701bf1543929599aafe4a81ed8d: removed 3 log segments from log reader
I20260812 06:19:03.373409 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000001 (ops 1-6)
I20260812 06:19:03.373454 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000002 (ops 7-11)
I20260812 06:19:03.373486 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000003 (ops 12-16)
I20260812 06:19:03.381503 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: LogGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.008s	user 0.002s	sys 0.003s Metrics: {}
I20260812 06:19:03.381980 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d): 20924071 bytes on disk
I20260812 06:19:03.382486 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":75,"lbm_reads_lt_1ms":4}
I20260812 06:19:03.382932 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:03.397348 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.014s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4765,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.397763 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:03.563794 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.166s	user 0.110s	sys 0.055s Metrics: {"cfile_cache_miss":522,"cfile_cache_miss_bytes":24446413,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":596,"lbm_read_time_us":12317,"lbm_reads_lt_1ms":550,"lbm_write_time_us":27169,"lbm_writes_lt_1ms":533,"peak_mem_usage":61665166,"reinsert_count":0,"spinlock_wait_cycles":2816,"thread_start_us":355,"threads_started":5,"update_count":2450}
I20260812 06:19:03.564268 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:03.614392 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.050s	user 0.029s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16504,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:03.614887 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:03.623968 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3443,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.624428 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:03.780759 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.156s	user 0.102s	sys 0.052s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1291,"lbm_read_time_us":11434,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27068,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":542,"mutex_wait_us":311,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2500}
I20260812 06:19:03.781289 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:03.832216 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.051s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18254,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:03.832680 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:03.842051 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3636,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:03.842443 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:04.006448 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.164s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856653,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":230,"lbm_read_time_us":11334,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27403,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":10880,"update_count":2500}
I20260812 06:19:04.006876 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:04.059055 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.052s	user 0.015s	sys 0.028s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15705,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.059566 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:04.073575 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.014s	user 0.011s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5475,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.073997 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:04.236899 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.163s	user 0.085s	sys 0.073s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":271,"lbm_read_time_us":11832,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25546,"lbm_writes_lt_1ms":543,"mutex_wait_us":55,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.237315 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:04.286334 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.049s	user 0.028s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19079,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.286825 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:04.305074 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.018s	user 0.008s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3539,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.305481 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:04.469990 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.164s	user 0.093s	sys 0.064s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":372,"lbm_read_time_us":11505,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24802,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:04.470472 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:04.519731 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.049s	user 0.021s	sys 0.022s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20146,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.520290 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:04.530118 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.530985 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:04.562114 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.031s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":70,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1310,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1304,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29,"spinlock_wait_cycles":7936}
I20260812 06:19:04.562731 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling LogGCOp(75e1c701bf1543929599aafe4a81ed8d): free 112692364 bytes of WAL
I20260812 06:19:04.562956 24080 log_reader.cc:385] T 75e1c701bf1543929599aafe4a81ed8d: removed 11 log segments from log reader
I20260812 06:19:04.563014 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000004 (ops 17-21)
I20260812 06:19:04.563054 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000005 (ops 22-26)
I20260812 06:19:04.563084 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000006 (ops 27-31)
I20260812 06:19:04.563115 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000007 (ops 32-36)
I20260812 06:19:04.563148 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000008 (ops 37-41)
I20260812 06:19:04.563177 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000009 (ops 42-46)
I20260812 06:19:04.563205 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000010 (ops 47-51)
I20260812 06:19:04.563230 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000011 (ops 52-56)
I20260812 06:19:04.563261 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000012 (ops 57-61)
I20260812 06:19:04.563292 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000013 (ops 62-66)
I20260812 06:19:04.563320 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000014 (ops 67-71)
I20260812 06:19:04.588706 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: LogGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.026s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:04.589089 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d): 462 bytes on disk
I20260812 06:19:04.589740 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":85,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.590224 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=3.181125
I20260812 06:19:04.615516 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.025s	user 0.007s	sys 0.005s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4666,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:04.615876 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:04.624275 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.008s	user 0.006s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3124,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.624594 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:04.848819 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.224s	user 0.158s	sys 0.063s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061700,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":107,"lbm_read_time_us":15219,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35580,"lbm_writes_lt_1ms":743,"mutex_wait_us":42,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1664,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:04.849328 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=18.063937
I20260812 06:19:04.916343 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.067s	user 0.030s	sys 0.024s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":25401,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:04.916751 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:04.926064 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3517,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.926690 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:05.117388 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.190s	user 0.124s	sys 0.063s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959068,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":165,"lbm_read_time_us":12909,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29126,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":7168,"update_count":3000}
I20260812 06:19:05.117959 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:05.153748 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.036s	user 0.026s	sys 0.007s Metrics: {"bytes_written":16450927,"delete_count":0,"lbm_write_time_us":15651,"lbm_writes_lt_1ms":404,"reinsert_count":0,"update_count":2005}
I20260812 06:19:05.154258 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.165380 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.011s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4061634,"delete_count":0,"lbm_write_time_us":3637,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":495}
I20260812 06:19:05.165848 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:05.329849 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.164s	user 0.117s	sys 0.045s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":194,"lbm_read_time_us":10979,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27269,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12544,"update_count":2500}
I20260812 06:19:05.330329 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:05.383409 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.053s	user 0.037s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18862,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.383953 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.393548 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3709,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.393970 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:05.550200 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.156s	user 0.108s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856654,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":889,"lbm_read_time_us":11121,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25691,"lbm_writes_lt_1ms":543,"mutex_wait_us":273,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:05.550909 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:05.610996 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.060s	user 0.026s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20463,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.611488 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.621228 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3718,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.621618 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:05.798609 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.177s	user 0.099s	sys 0.072s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856652,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":664,"lbm_read_time_us":12903,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26358,"lbm_writes_lt_1ms":543,"mutex_wait_us":310,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20864,"update_count":2500}
I20260812 06:19:05.799180 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=14.095187
I20260812 06:19:05.844408 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.045s	user 0.019s	sys 0.017s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":16387,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.844923 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.865595 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.021s	user 0.014s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5103,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.866015 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:05.900028 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.034s	user 0.024s	sys 0.000s Metrics: {"bytes_written":1152514,"cfile_init":1,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":197,"dirs.run_wall_time_us":956,"drs_written":1,"lbm_read_time_us":34,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1212,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:05.900664 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling LogGCOp(75e1c701bf1543929599aafe4a81ed8d): free 112239318 bytes of WAL
I20260812 06:19:05.900874 24080 log_reader.cc:385] T 75e1c701bf1543929599aafe4a81ed8d: removed 11 log segments from log reader
I20260812 06:19:05.900919 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000015 (ops 72-76)
I20260812 06:19:05.900947 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000016 (ops 77-80)
I20260812 06:19:05.900979 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000017 (ops 81-85)
I20260812 06:19:05.901010 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000018 (ops 86-90)
I20260812 06:19:05.901036 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000019 (ops 91-95)
I20260812 06:19:05.901067 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000020 (ops 96-100)
I20260812 06:19:05.901118 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000021 (ops 101-105)
I20260812 06:19:05.901153 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000022 (ops 106-110)
I20260812 06:19:05.901185 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000023 (ops 111-115)
I20260812 06:19:05.901217 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000024 (ops 116-120)
I20260812 06:19:05.901249 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000025 (ops 121-125)
I20260812 06:19:05.921643 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: LogGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.021s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:19:05.922050 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d): 447 bytes on disk
I20260812 06:19:05.922566 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d) 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:05.923318 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.941905 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.018s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4811,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.942260 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:05.951400 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.009s	user 0.007s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3470,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.951828 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:06.184464 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.232s	user 0.137s	sys 0.086s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061716,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":568,"lbm_read_time_us":15667,"lbm_reads_lt_1ms":774,"lbm_write_time_us":37810,"lbm_writes_lt_1ms":743,"mutex_wait_us":312,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":15232,"thread_start_us":73,"threads_started":1,"update_count":3500}
I20260812 06:19:06.185343 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=18.063937
I20260812 06:19:06.248669 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.063s	user 0.036s	sys 0.012s Metrics: {"bytes_written":20512314,"delete_count":0,"lbm_write_time_us":22305,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:06.249161 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:06.264117 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5816,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.264734 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:06.444362 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.179s	user 0.112s	sys 0.067s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959066,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":253,"lbm_read_time_us":13121,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29233,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":51840,"update_count":3000}
I20260812 06:19:06.444948 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=15.087375
I20260812 06:19:06.489130 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.044s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16820140,"delete_count":0,"lbm_write_time_us":18878,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:06.489624 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:06.512060 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.022s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.512513 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:06.522416 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3867,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.522872 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:06.706450 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.183s	user 0.126s	sys 0.056s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959168,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":892,"lbm_read_time_us":12531,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29194,"lbm_writes_lt_1ms":643,"mutex_wait_us":302,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":3000}
I20260812 06:19:06.710013 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=15.087375
I20260812 06:19:06.761729 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.051s	user 0.018s	sys 0.029s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":22683,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:06.762223 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:06.785784 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.023s	user 0.001s	sys 0.009s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4624,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.786273 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:06.800034 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.800511 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:06.991025 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.190s	user 0.106s	sys 0.082s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959171,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1148,"lbm_read_time_us":11769,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32216,"lbm_writes_lt_1ms":643,"mutex_wait_us":272,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2816,"update_count":3000}
I20260812 06:19:06.991586 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=16.079562
I20260812 06:19:07.057062 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.065s	user 0.012s	sys 0.036s Metrics: {"bytes_written":18338037,"delete_count":0,"lbm_write_time_us":22871,"lbm_writes_lt_1ms":450,"reinsert_count":0,"update_count":2235}
I20260812 06:19:07.057507 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=5.165500
I20260812 06:19:07.072623 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":6276948,"delete_count":0,"lbm_write_time_us":6049,"lbm_writes_lt_1ms":156,"reinsert_count":0,"update_count":765}
I20260812 06:19:07.073055 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:07.275916 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.203s	user 0.136s	sys 0.056s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959072,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":590,"lbm_read_time_us":13238,"lbm_reads_lt_1ms":672,"lbm_write_time_us":29651,"lbm_writes_lt_1ms":643,"mutex_wait_us":237,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4224,"update_count":3000}
I20260812 06:19:07.276468 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=18.063937
I20260812 06:19:07.327571 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.051s	user 0.030s	sys 0.020s Metrics: {"bytes_written":20512318,"delete_count":0,"lbm_write_time_us":22958,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.328079 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:07.368688 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushMRSOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.040s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":242,"dirs.run_wall_time_us":1246,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2254,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:07.369349 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=3.181125
I20260812 06:19:07.382179 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.013s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4430852,"delete_count":0,"lbm_write_time_us":4086,"lbm_writes_lt_1ms":111,"reinsert_count":0,"update_count":540}
I20260812 06:19:07.382687 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling LogGCOp(75e1c701bf1543929599aafe4a81ed8d): free 133024640 bytes of WAL
I20260812 06:19:07.382929 24080 log_reader.cc:385] T 75e1c701bf1543929599aafe4a81ed8d: removed 13 log segments from log reader
I20260812 06:19:07.382977 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000026 (ops 126-130)
I20260812 06:19:07.383014 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000027 (ops 131-135)
I20260812 06:19:07.383049 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000028 (ops 136-140)
I20260812 06:19:07.383080 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000029 (ops 141-145)
I20260812 06:19:07.383104 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000030 (ops 146-150)
I20260812 06:19:07.383136 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000031 (ops 151-155)
I20260812 06:19:07.383167 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000032 (ops 156-160)
I20260812 06:19:07.383198 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000033 (ops 161-165)
I20260812 06:19:07.383227 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000034 (ops 166-170)
I20260812 06:19:07.383258 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000035 (ops 171-174)
I20260812 06:19:07.383288 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000036 (ops 175-179)
I20260812 06:19:07.383318 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000037 (ops 180-184)
I20260812 06:19:07.383348 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000038 (ops 185-189)
I20260812 06:19:07.407398 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: LogGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.025s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:19:07.407841 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d): 493 bytes on disk
I20260812 06:19:07.408303 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: UndoDeltaBlockGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4}
I20260812 06:19:07.408932 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:07.423902 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.015s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4184711,"delete_count":0,"lbm_write_time_us":3720,"lbm_writes_lt_1ms":105,"reinsert_count":0,"update_count":510}
I20260812 06:19:07.424265 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling LogGCOp(75e1c701bf1543929599aafe4a81ed8d): free 12017954 bytes of WAL
I20260812 06:19:07.424463 24080 log_reader.cc:385] T 75e1c701bf1543929599aafe4a81ed8d: removed 1 log segments from log reader
I20260812 06:19:07.424504 24080 log.cc:1079] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: Deleting log segment in path: /tmp/dist-test-taskDuZbAR/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515537811151-23517-0/minicluster-data/ts-0-root/wals/75e1c701bf1543929599aafe4a81ed8d/wal-000000039 (ops 190-194)
I20260812 06:19:07.426470 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: LogGCOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.002s	user 0.000s	sys 0.002s Metrics: {}
I20260812 06:19:07.426729 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=2.188937
I20260812 06:19:07.435354 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.008s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3195,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:07.435896 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d): perf score=1.000000
I20260812 06:19:07.548015 23517 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.510s	user 1.626s	sys 0.163s
I20260812 06:19:07.651851 23517 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.002s	sys 0.000s
I20260812 06:19:07.652334 23517 tablet_server.cc:179] TabletServer@127.22.247.65:0 shutting down...
I20260812 06:19:07.655059 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: MajorDeltaCompactionOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.219s	user 0.137s	sys 0.075s Metrics: {"cfile_cache_miss":834,"cfile_cache_miss_bytes":37164123,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":888,"lbm_read_time_us":16940,"lbm_reads_lt_1ms":870,"lbm_write_time_us":35965,"lbm_writes_lt_1ms":843,"mutex_wait_us":317,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":24320,"thread_start_us":343,"threads_started":1,"update_count":4000}
I20260812 06:19:07.655556 24180 maintenance_manager.cc:419] P 77df7980567a4b52834713568b280898: Scheduling FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d): perf score=10.126437
I20260812 06:19:07.681499 24080 maintenance_manager.cc:643] P 77df7980567a4b52834713568b280898: FlushDeltaMemStoresOp(75e1c701bf1543929599aafe4a81ed8d) complete. Timing: real 0.026s	user 0.003s	sys 0.020s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":11128,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:07.681978 23517 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:07.682170 23517 tablet_replica.cc:333] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898: stopping tablet replica
I20260812 06:19:07.682301 23517 raft_consensus.cc:2243] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.682474 23517 raft_consensus.cc:2272] T 75e1c701bf1543929599aafe4a81ed8d P 77df7980567a4b52834713568b280898 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.695294 23517 tablet_server.cc:196] TabletServer@127.22.247.65:0 shutdown complete.
I20260812 06:19:07.725800 23517 master.cc:562] Master@127.22.247.126:40747 shutting down...
I20260812 06:19:07.728592 23517 raft_consensus.cc:2243] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:07.728746 23517 raft_consensus.cc:2272] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:07.728809 23517 tablet_replica.cc:333] T 00000000000000000000000000000000 P dae59b26f5344fb085f11220023e0ea7: stopping tablet replica
I20260812 06:19:07.740783 23517 master.cc:584] Master@127.22.247.126:40747 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4955 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9993 ms total)

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