[==========] 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:17:02.321055 19225 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.198.126:46289
I20260812 06:17:02.321997 19225 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:17:02.322551 19225 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.328073 19243 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:17:02.328143 19240 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:17:02.328272 19225 server_base.cc:1061] running on GCE node
W20260812 06:17:02.328411 19239 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:17:02.328855 19225 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.328949 19225 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:17:02.328991 19225 hybrid_clock.cc:648] HybridClock initialized: now 1786515422328989 us; error 0 us; skew 500 ppm
I20260812 06:17:02.330595 19225 webserver.cc:533] Webserver started at http://127.18.198.126:36941/ using document root <none> and password file <none>
I20260812 06:17:02.331074 19225 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.331128 19225 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.331337 19225 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.332862 19225 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/master-0-root/instance:
uuid: "4f02a6cafa7d43359df25767d83b0140"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-2j7r"
I20260812 06:17:02.336028 19225 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.001s
I20260812 06:17:02.337888 19251 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:17:02.338784 19225 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:02.338883 19225 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/master-0-root
uuid: "4f02a6cafa7d43359df25767d83b0140"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-2j7r"
I20260812 06:17:02.338966 19225 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-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:17:02.352145 19225 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.352648 19225 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:17:02.352782 19225 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.359640 19341 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.198.126:46289 every 8 connection(s)
I20260812 06:17:02.359644 19225 rpc_server.cc:307] RPC server started. Bound to: 127.18.198.126:46289
I20260812 06:17:02.361734 19347 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:17:02.366772 19347 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: Bootstrap starting.
I20260812 06:17:02.368906 19347 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.369738 19347 log.cc:826] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: Log is configured to *not* fsync() on all Append() calls
I20260812 06:17:02.371191 19347 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: No bootstrap required, opened a new log
I20260812 06:17:02.373775 19347 raft_consensus.cc:359] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER }
I20260812 06:17:02.373925 19347 raft_consensus.cc:385] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.373978 19347 raft_consensus.cc:740] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4f02a6cafa7d43359df25767d83b0140, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.374462 19347 consensus_queue.cc:260] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [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: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER }
I20260812 06:17:02.374584 19347 raft_consensus.cc:399] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.374629 19347 raft_consensus.cc:493] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.374719 19347 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.375367 19347 raft_consensus.cc:515] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER }
I20260812 06:17:02.375731 19347 leader_election.cc:304] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [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: 4f02a6cafa7d43359df25767d83b0140; no voters: 
I20260812 06:17:02.375973 19347 leader_election.cc:290] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.376127 19352 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.376365 19352 raft_consensus.cc:697] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 1 LEADER]: Becoming Leader. State: Replica: 4f02a6cafa7d43359df25767d83b0140, State: Running, Role: LEADER
I20260812 06:17:02.376753 19352 consensus_queue.cc:237] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [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: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER }
I20260812 06:17:02.376803 19347 sys_catalog.cc:565] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:02.378588 19353 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "4f02a6cafa7d43359df25767d83b0140" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER } }
I20260812 06:17:02.378705 19353 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.378929 19355 sys_catalog.cc:455] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 4f02a6cafa7d43359df25767d83b0140. Latest consensus state: current_term: 1 leader_uuid: "4f02a6cafa7d43359df25767d83b0140" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4f02a6cafa7d43359df25767d83b0140" member_type: VOTER } }
I20260812 06:17:02.378957 19225 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:02.379012 19355 sys_catalog.cc:458] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:02.379024 19372 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:02.381146 19372 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:02.385483 19372 catalog_manager.cc:1383] Generated new cluster ID: 43939ec5030e4eac8b7dc99b0858fde3
I20260812 06:17:02.385545 19372 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:02.403825 19372 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:02.404570 19372 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:02.411936 19372 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: Generated new TSK 0
I20260812 06:17:02.412458 19372 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:02.443536 19225 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:02.445981 19384 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:17:02.446138 19225 server_base.cc:1061] running on GCE node
W20260812 06:17:02.446069 19389 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:17:02.446249 19386 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:17:02.446476 19225 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:02.446519 19225 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:17:02.446540 19225 hybrid_clock.cc:648] HybridClock initialized: now 1786515422446540 us; error 0 us; skew 500 ppm
I20260812 06:17:02.447348 19225 webserver.cc:533] Webserver started at http://127.18.198.65:33273/ using document root <none> and password file <none>
I20260812 06:17:02.447515 19225 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:02.447562 19225 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:02.447633 19225 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:02.447984 19225 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/instance:
uuid: "b45088563bf44ea9a181227f9dece127"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-2j7r"
I20260812 06:17:02.449486 19225 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:17:02.450384 19405 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:17:02.450613 19225 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:02.450678 19225 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root
uuid: "b45088563bf44ea9a181227f9dece127"
format_stamp: "Formatted at 2026-08-12 06:17:02 on dist-test-slave-2j7r"
I20260812 06:17:02.450753 19225 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-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:17:02.454718 19225 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:02.455051 19225 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:02.455482 19225 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:02.456250 19225 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:02.456302 19225 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.456346 19225 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:02.456386 19225 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:02.462634 19225 rpc_server.cc:307] RPC server started. Bound to: 127.18.198.65:39939
I20260812 06:17:02.462848 19535 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.198.65:39939 every 8 connection(s)
I20260812 06:17:02.475852 19536 heartbeater.cc:344] Connected to a master server at 127.18.198.126:46289
I20260812 06:17:02.476085 19536 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:02.476533 19536 heartbeater.cc:507] Master 127.18.198.126:46289 requested a full tablet report, sending...
I20260812 06:17:02.477952 19274 ts_manager.cc:194] Registered new tserver with Master: b45088563bf44ea9a181227f9dece127 (127.18.198.65:39939)
I20260812 06:17:02.478829 19225 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.015568313s
I20260812 06:17:02.479197 19274 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:38574
I20260812 06:17:02.487514 19274 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:38584:
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:17:02.501837 19456 tablet_service.cc:1511] Processing CreateTablet for tablet 249d6ba9844d48ef8383bc4022ed05cc (DEFAULT_TABLE table=heavy-update-compaction-test [id=353ddc4e98734371afe38ee45962148b]), partition=
I20260812 06:17:02.502238 19456 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 249d6ba9844d48ef8383bc4022ed05cc. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:02.504364 19561 tablet_bootstrap.cc:492] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Bootstrap starting.
I20260812 06:17:02.505297 19561 tablet_bootstrap.cc:654] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:02.506428 19561 tablet_bootstrap.cc:492] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: No bootstrap required, opened a new log
I20260812 06:17:02.506515 19561 ts_tablet_manager.cc:1403] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:02.507133 19561 raft_consensus.cc:359] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b45088563bf44ea9a181227f9dece127" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 39939 } }
I20260812 06:17:02.507226 19561 raft_consensus.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:02.507256 19561 raft_consensus.cc:740] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: b45088563bf44ea9a181227f9dece127, State: Initialized, Role: FOLLOWER
I20260812 06:17:02.507375 19561 consensus_queue.cc:260] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [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: "b45088563bf44ea9a181227f9dece127" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 39939 } }
I20260812 06:17:02.507441 19561 raft_consensus.cc:399] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:02.507483 19561 raft_consensus.cc:493] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:02.507529 19561 raft_consensus.cc:3060] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:02.508198 19561 raft_consensus.cc:515] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b45088563bf44ea9a181227f9dece127" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 39939 } }
I20260812 06:17:02.508322 19561 leader_election.cc:304] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [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: b45088563bf44ea9a181227f9dece127; no voters: 
I20260812 06:17:02.508489 19561 leader_election.cc:290] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:02.508598 19564 raft_consensus.cc:2804] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:02.508814 19561 ts_tablet_manager.cc:1434] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Time spent starting tablet: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:17:02.508828 19564 raft_consensus.cc:697] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 1 LEADER]: Becoming Leader. State: Replica: b45088563bf44ea9a181227f9dece127, State: Running, Role: LEADER
I20260812 06:17:02.509006 19536 heartbeater.cc:499] Master 127.18.198.126:46289 was elected leader, sending a full tablet report...
I20260812 06:17:02.509043 19564 consensus_queue.cc:237] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [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: "b45088563bf44ea9a181227f9dece127" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 39939 } }
I20260812 06:17:02.511443 19274 catalog_manager.cc:5719] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 reported cstate change: term changed from 0 to 1, leader changed from <none> to b45088563bf44ea9a181227f9dece127 (127.18.198.65). New cstate: current_term: 1 leader_uuid: "b45088563bf44ea9a181227f9dece127" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "b45088563bf44ea9a181227f9dece127" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 39939 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:02.566694 19225 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.050s	user 0.016s	sys 0.008s
I20260812 06:17:02.713687 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=23.023690
I20260812 06:17:02.919363 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.205s	user 0.156s	sys 0.044s Metrics: {"bytes_written":16409901,"cfile_init":1,"compiler_manager_pool.queue_time_us":207,"delete_count":0,"dirs.queue_time_us":78,"dirs.run_cpu_time_us":176,"dirs.run_wall_time_us":744,"drs_written":1,"lbm_read_time_us":73,"lbm_reads_lt_1ms":4,"lbm_write_time_us":52369,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"thread_start_us":122,"threads_started":1,"update_count":2000}
I20260812 06:17:02.920718 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 20743880 bytes of WAL
I20260812 06:17:02.921181 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 2 log segments from log reader
I20260812 06:17:02.921315 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000001 (ops 1-6)
I20260812 06:17:02.921452 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000002 (ops 7-11)
I20260812 06:17:02.925773 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.005s	user 0.001s	sys 0.003s Metrics: {}
I20260812 06:17:02.926127 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:02.940223 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5091,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:02.940661 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc): 20513814 bytes on disk
I20260812 06:17:02.941248 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:02.941663 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:03.099395 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.158s	user 0.130s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":462,"lbm_read_time_us":9176,"lbm_reads_lt_1ms":560,"lbm_write_time_us":25428,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"thread_start_us":308,"threads_started":5,"update_count":2500}
I20260812 06:17:03.099861 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:03.156064 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.056s	user 0.023s	sys 0.027s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19966,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:03.156530 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:03.166200 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.010s	user 0.000s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3719,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.166567 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:03.322665 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.156s	user 0.092s	sys 0.061s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":171,"lbm_read_time_us":10253,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24830,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:03.323171 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=11.118625
I20260812 06:17:03.360762 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.037s	user 0.018s	sys 0.016s Metrics: {"bytes_written":12717737,"delete_count":0,"lbm_write_time_us":16471,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:03.361343 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:03.372948 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.011s	user 0.009s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4526,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:03.373440 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:03.504791 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.131s	user 0.087s	sys 0.039s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713265,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":7895,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22609,"lbm_writes_lt_1ms":443,"mutex_wait_us":23,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":11648,"update_count":2000}
I20260812 06:17:03.505314 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=10.126437
I20260812 06:17:03.550568 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.045s	user 0.019s	sys 0.025s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":21857,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":301,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.551087 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:03.566679 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.567287 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:03.682471 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.115s	user 0.083s	sys 0.032s 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":1449,"lbm_read_time_us":7633,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23695,"lbm_writes_lt_1ms":443,"mutex_wait_us":360,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":5248,"update_count":2000}
I20260812 06:17:03.682931 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=10.126437
I20260812 06:17:03.721675 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.039s	user 0.021s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":18104,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.722158 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:03.737419 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4576,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.737900 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:03.863072 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.125s	user 0.086s	sys 0.038s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":141,"lbm_read_time_us":9811,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24984,"lbm_writes_lt_1ms":443,"mutex_wait_us":18,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:17:03.863560 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=10.126437
I20260812 06:17:03.900295 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.037s	user 0.005s	sys 0.028s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12884,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:03.900897 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:03.913908 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.013s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4502,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:03.914330 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.053990 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.139s	user 0.102s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713271,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":234,"lbm_read_time_us":11301,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23500,"lbm_writes_lt_1ms":443,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:17:04.054605 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=10.126437
I20260812 06:17:04.085727 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.031s	user 0.019s	sys 0.012s Metrics: {"bytes_written":12430563,"delete_count":0,"lbm_write_time_us":13822,"lbm_writes_lt_1ms":306,"reinsert_count":0,"update_count":1515}
I20260812 06:17:04.086299 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:04.099231 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.013s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3979584,"delete_count":0,"lbm_write_time_us":5152,"lbm_writes_lt_1ms":100,"reinsert_count":0,"update_count":485}
I20260812 06:17:04.099686 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.130956 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.031s	user 0.022s	sys 0.007s Metrics: {"bytes_written":1275444,"cfile_init":1,"dirs.queue_time_us":64,"dirs.run_cpu_time_us":228,"dirs.run_wall_time_us":1253,"drs_written":1,"lbm_read_time_us":56,"lbm_reads_lt_1ms":4,"lbm_write_time_us":2095,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31}
I20260812 06:17:04.131739 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 121006425 bytes of WAL
I20260812 06:17:04.132032 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 12 log segments from log reader
I20260812 06:17:04.132114 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000003 (ops 12-16)
I20260812 06:17:04.132161 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000004 (ops 17-21)
I20260812 06:17:04.132207 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000005 (ops 22-26)
I20260812 06:17:04.132259 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000006 (ops 27-31)
I20260812 06:17:04.132293 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000007 (ops 32-36)
I20260812 06:17:04.132339 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000008 (ops 37-41)
I20260812 06:17:04.132391 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000009 (ops 42-46)
I20260812 06:17:04.132428 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000010 (ops 47-51)
I20260812 06:17:04.132465 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000011 (ops 52-56)
I20260812 06:17:04.132500 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000012 (ops 57-60)
I20260812 06:17:04.132535 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000013 (ops 61-65)
I20260812 06:17:04.132570 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000014 (ops 66-70)
I20260812 06:17:04.158178 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.026s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:04.158604 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc): 482 bytes on disk
I20260812 06:17:04.159103 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":69,"lbm_reads_lt_1ms":4}
I20260812 06:17:04.159612 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=4.173312
I20260812 06:17:04.183137 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.023s	user 0.010s	sys 0.011s Metrics: {"bytes_written":6112849,"delete_count":0,"lbm_write_time_us":6931,"lbm_writes_lt_1ms":152,"reinsert_count":0,"update_count":745}
I20260812 06:17:04.183562 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 12017935 bytes of WAL
I20260812 06:17:04.183768 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 1 log segments from log reader
I20260812 06:17:04.183827 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000015 (ops 71-75)
I20260812 06:17:04.186854 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.003s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:17:04.187186 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.196276 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.009s	user 0.003s	sys 0.004s Metrics: {"bytes_written":2092427,"delete_count":0,"lbm_write_time_us":2987,"lbm_writes_lt_1ms":54,"reinsert_count":0,"update_count":255}
I20260812 06:17:04.196776 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.389127 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.192s	user 0.136s	sys 0.047s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918285,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":621,"lbm_read_time_us":13668,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31905,"lbm_writes_lt_1ms":643,"mutex_wait_us":45,"peak_mem_usage":75542472,"reinsert_count":0,"thread_start_us":67,"threads_started":1,"update_count":3000}
I20260812 06:17:04.389638 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:04.441918 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.052s	user 0.027s	sys 0.019s Metrics: {"bytes_written":16409906,"delete_count":0,"lbm_write_time_us":17453,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.442427 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:04.452515 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.010s	user 0.002s	sys 0.006s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3859,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.452913 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.621804 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.169s	user 0.145s	sys 0.024s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":536,"lbm_read_time_us":12676,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28791,"lbm_writes_lt_1ms":543,"mutex_wait_us":24,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:17:04.622301 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=11.118625
I20260812 06:17:04.664206 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.042s	user 0.018s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18009,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:04.664714 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:04.687304 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.022s	user 0.010s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4488,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:04.687706 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:04.697571 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4057,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.697955 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:04.878273 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.180s	user 0.116s	sys 0.052s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815793,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":88,"lbm_read_time_us":10127,"lbm_reads_lt_1ms":573,"lbm_write_time_us":30028,"lbm_writes_lt_1ms":543,"mutex_wait_us":36,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2500}
I20260812 06:17:04.878876 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:04.929061 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.050s	user 0.016s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19041,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:04.929598 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:04.945470 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.016s	user 0.015s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6141,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:04.945999 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.091739 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.146s	user 0.092s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":392,"lbm_read_time_us":11110,"lbm_reads_lt_1ms":564,"lbm_write_time_us":27875,"lbm_writes_lt_1ms":543,"mutex_wait_us":95,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3072,"update_count":2500}
I20260812 06:17:05.092411 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=11.118625
I20260812 06:17:05.135236 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.043s	user 0.021s	sys 0.019s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":18885,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:05.135737 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.151960 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.016s	user 0.009s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.152395 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.161911 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.009s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.162288 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.301888 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.139s	user 0.107s	sys 0.027s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815794,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":141,"lbm_read_time_us":9535,"lbm_reads_lt_1ms":573,"lbm_write_time_us":28656,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2500}
I20260812 06:17:05.302386 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=11.118625
I20260812 06:17:05.336444 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.034s	user 0.020s	sys 0.011s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":14981,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:17:05.337020 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.354338 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.017s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5171,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.354830 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.469167 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.114s	user 0.100s	sys 0.014s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713264,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":423,"lbm_read_time_us":6934,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22082,"lbm_writes_lt_1ms":443,"mutex_wait_us":117,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":2000}
I20260812 06:17:05.469688 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=10.126437
I20260812 06:17:05.504324 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.034s	user 0.019s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13571,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:17:05.504801 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.514952 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.010s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3783,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.515555 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.543687 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.028s	user 0.025s	sys 0.001s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":170,"dirs.run_wall_time_us":1315,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1512,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:17:05.544340 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 112692387 bytes of WAL
I20260812 06:17:05.544556 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 11 log segments from log reader
I20260812 06:17:05.544601 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000016 (ops 76-80)
I20260812 06:17:05.544629 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000017 (ops 81-85)
I20260812 06:17:05.544661 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000018 (ops 86-90)
I20260812 06:17:05.544692 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000019 (ops 91-95)
I20260812 06:17:05.544724 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000020 (ops 96-100)
I20260812 06:17:05.544755 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000021 (ops 101-105)
I20260812 06:17:05.544787 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000022 (ops 106-110)
I20260812 06:17:05.544818 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000023 (ops 111-115)
I20260812 06:17:05.544850 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000024 (ops 116-120)
I20260812 06:17:05.544881 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000025 (ops 121-125)
I20260812 06:17:05.544914 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000026 (ops 126-130)
I20260812 06:17:05.565680 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.021s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:17:05.566187 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=3.181125
I20260812 06:17:05.582480 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.016s	user 0.008s	sys 0.002s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":4161,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:05.582919 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc): 463 bytes on disk
I20260812 06:17:05.583422 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":64,"lbm_reads_lt_1ms":4}
I20260812 06:17:05.583992 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.593768 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.010s	user 0.008s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3666,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:05.594496 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.756740 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.162s	user 0.110s	sys 0.049s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918324,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":1160,"lbm_read_time_us":11680,"lbm_reads_lt_1ms":674,"lbm_write_time_us":32153,"lbm_writes_lt_1ms":643,"mutex_wait_us":612,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14976,"thread_start_us":91,"threads_started":1,"update_count":3000}
I20260812 06:17:05.757366 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:05.800836 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.043s	user 0.025s	sys 0.016s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18525,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:05.801393 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.821614 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.020s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4319,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.822068 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:05.831518 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.009s	user 0.005s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3690,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:05.831887 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:05.995585 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.164s	user 0.136s	sys 0.028s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918213,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":216,"lbm_read_time_us":13049,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34092,"lbm_writes_lt_1ms":643,"mutex_wait_us":41,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9600,"update_count":3000}
I20260812 06:17:05.996197 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:06.036507 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.040s	user 0.014s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18052,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.037057 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:06.049240 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.012s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4311,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.049724 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:06.203622 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.154s	user 0.106s	sys 0.040s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":355,"lbm_read_time_us":9583,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29433,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":2500}
I20260812 06:17:06.204242 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:06.247960 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.044s	user 0.030s	sys 0.008s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":18027,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.248467 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:06.393270 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.145s	user 0.079s	sys 0.058s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713154,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":3388,"lbm_read_time_us":10237,"lbm_reads_lt_1ms":463,"lbm_write_time_us":21973,"lbm_writes_lt_1ms":443,"mutex_wait_us":2738,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":2000}
I20260812 06:17:06.393796 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:06.436488 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.043s	user 0.028s	sys 0.009s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18642,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.436986 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:06.452116 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5952,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.452605 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:06.641201 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.188s	user 0.132s	sys 0.043s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":499,"lbm_read_time_us":11455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29995,"lbm_writes_lt_1ms":543,"mutex_wait_us":40,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:17:06.641680 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=14.095187
I20260812 06:17:06.687788 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.046s	user 0.033s	sys 0.008s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":20610,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:06.688362 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:06.708426 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.020s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5345,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.708914 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:06.745678 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushMRSOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.037s	user 0.021s	sys 0.002s Metrics: {"bytes_written":1152512,"cfile_init":1,"dirs.queue_time_us":54,"dirs.run_cpu_time_us":215,"dirs.run_wall_time_us":1379,"drs_written":1,"lbm_read_time_us":38,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1428,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:17:06.746451 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc): 447 bytes on disk
I20260812 06:17:06.746814 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: UndoDeltaBlockGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":57,"lbm_reads_lt_1ms":4}
I20260812 06:17:06.747411 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=3.181125
I20260812 06:17:06.766108 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.019s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4512903,"delete_count":0,"lbm_write_time_us":5213,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:06.766566 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 115943419 bytes of WAL
I20260812 06:17:06.766791 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 11 log segments from log reader
I20260812 06:17:06.766836 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000027 (ops 131-135)
I20260812 06:17:06.766875 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000028 (ops 136-140)
I20260812 06:17:06.766906 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000029 (ops 141-145)
I20260812 06:17:06.766938 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000030 (ops 146-150)
I20260812 06:17:06.766968 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000031 (ops 151-155)
I20260812 06:17:06.767000 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000032 (ops 156-160)
I20260812 06:17:06.767030 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000033 (ops 161-165)
I20260812 06:17:06.767060 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000034 (ops 166-170)
I20260812 06:17:06.767091 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000035 (ops 171-175)
I20260812 06:17:06.767122 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000036 (ops 176-180)
I20260812 06:17:06.767153 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000037 (ops 181-185)
I20260812 06:17:06.788426 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.022s	user 0.000s	sys 0.018s Metrics: {}
I20260812 06:17:06.788822 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:06.800843 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.012s	user 0.007s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4631,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:06.801316 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling LogGCOp(249d6ba9844d48ef8383bc4022ed05cc): free 12017952 bytes of WAL
I20260812 06:17:06.801522 19411 log_reader.cc:385] T 249d6ba9844d48ef8383bc4022ed05cc: removed 1 log segments from log reader
I20260812 06:17:06.801568 19411 log.cc:1079] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/249d6ba9844d48ef8383bc4022ed05cc/wal-000000038 (ops 186-190)
I20260812 06:17:06.803478 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: LogGCOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.002s	user 0.000s	sys 0.000s Metrics: {}
I20260812 06:17:06.803903 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:07.033535 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.229s	user 0.155s	sys 0.072s Metrics: {"cfile_cache_miss":744,"cfile_cache_miss_bytes":33430989,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":6681,"lbm_read_time_us":15390,"lbm_reads_lt_1ms":776,"lbm_write_time_us":38056,"lbm_writes_lt_1ms":753,"mutex_wait_us":2238,"peak_mem_usage":88379394,"reinsert_count":0,"spinlock_wait_cycles":896,"thread_start_us":70,"threads_started":1,"update_count":3550}
I20260812 06:17:07.034111 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=18.063937
I20260812 06:17:07.093578 19225 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.527s	user 1.608s	sys 0.155s
I20260812 06:17:07.096740 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.062s	user 0.038s	sys 0.009s Metrics: {"bytes_written":20102073,"delete_count":0,"lbm_write_time_us":22194,"lbm_writes_lt_1ms":493,"reinsert_count":0,"update_count":2450}
I20260812 06:17:07.097301 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=2.188937
I20260812 06:17:07.106287 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: FlushDeltaMemStoresOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.009s	user 0.008s	sys 0.000s 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:17:07.106729 19539 maintenance_manager.cc:419] P b45088563bf44ea9a181227f9dece127: Scheduling MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc): perf score=1.000000
I20260812 06:17:07.159081 19225 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.002s	sys 0.000s
I20260812 06:17:07.159646 19225 tablet_server.cc:179] TabletServer@127.18.198.65:0 shutting down...
I20260812 06:17:07.249289 19411 maintenance_manager.cc:643] P b45088563bf44ea9a181227f9dece127: MajorDeltaCompactionOp(249d6ba9844d48ef8383bc4022ed05cc) complete. Timing: real 0.142s	user 0.111s	sys 0.028s Metrics: {"cfile_cache_hit":239,"cfile_cache_hit_bytes":9767167,"cfile_cache_miss":383,"cfile_cache_miss_bytes":18740688,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":3663,"lbm_read_time_us":7207,"lbm_reads_lt_1ms":415,"lbm_write_time_us":26540,"lbm_writes_lt_1ms":633,"mutex_wait_us":3138,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2950}
I20260812 06:17:07.249905 19225 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:07.250339 19225 tablet_replica.cc:333] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127: stopping tablet replica
I20260812 06:17:07.250561 19225 raft_consensus.cc:2243] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.250778 19225 raft_consensus.cc:2272] T 249d6ba9844d48ef8383bc4022ed05cc P b45088563bf44ea9a181227f9dece127 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.265657 19225 tablet_server.cc:196] TabletServer@127.18.198.65:0 shutdown complete.
I20260812 06:17:07.296872 19225 master.cc:562] Master@127.18.198.126:46289 shutting down...
I20260812 06:17:07.300472 19225 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:07.300631 19225 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:07.300706 19225 tablet_replica.cc:333] T 00000000000000000000000000000000 P 4f02a6cafa7d43359df25767d83b0140: stopping tablet replica
I20260812 06:17:07.312851 19225 master.cc:584] Master@127.18.198.126:46289 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5069 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:17:07.401644 19225 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.18.198.126:35023
I20260812 06:17:07.402055 19225 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:07.403975 19606 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:17:07.404095 19600 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:17:07.404143 19225 server_base.cc:1061] running on GCE node
W20260812 06:17:07.404199 19599 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:17:07.404472 19225 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:07.404516 19225 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:17:07.404529 19225 hybrid_clock.cc:648] HybridClock initialized: now 1786515427404530 us; error 0 us; skew 500 ppm
I20260812 06:17:07.405282 19225 webserver.cc:533] Webserver started at http://127.18.198.126:32895/ using document root <none> and password file <none>
I20260812 06:17:07.405445 19225 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:07.405496 19225 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:07.405553 19225 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:07.405906 19225 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/master-0-root/instance:
uuid: "64dbb5c83cfd4521aa222025e6c28095"
format_stamp: "Formatted at 2026-08-12 06:17:07 on dist-test-slave-2j7r"
I20260812 06:17:07.407296 19225 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:07.408186 19616 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:17:07.408397 19225 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:07.408464 19225 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/master-0-root
uuid: "64dbb5c83cfd4521aa222025e6c28095"
format_stamp: "Formatted at 2026-08-12 06:17:07 on dist-test-slave-2j7r"
I20260812 06:17:07.408527 19225 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-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:17:07.421398 19225 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:07.421689 19225 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:07.425448 19225 rpc_server.cc:307] RPC server started. Bound to: 127.18.198.126:35023
I20260812 06:17:07.430398 19711 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.198.126:35023 every 8 connection(s)
I20260812 06:17:07.430799 19712 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:17:07.432435 19712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095: Bootstrap starting.
I20260812 06:17:07.433205 19712 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:07.434135 19712 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095: No bootstrap required, opened a new log
I20260812 06:17:07.434496 19712 raft_consensus.cc:359] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER }
I20260812 06:17:07.434580 19712 raft_consensus.cc:385] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:07.434610 19712 raft_consensus.cc:740] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 64dbb5c83cfd4521aa222025e6c28095, State: Initialized, Role: FOLLOWER
I20260812 06:17:07.434753 19712 consensus_queue.cc:260] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [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: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER }
I20260812 06:17:07.434850 19712 raft_consensus.cc:399] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:07.434891 19712 raft_consensus.cc:493] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:07.434942 19712 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:07.435575 19712 raft_consensus.cc:515] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER }
I20260812 06:17:07.435702 19712 leader_election.cc:304] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [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: 64dbb5c83cfd4521aa222025e6c28095; no voters: 
I20260812 06:17:07.435880 19712 leader_election.cc:290] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:07.436014 19717 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:07.436203 19717 raft_consensus.cc:697] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 1 LEADER]: Becoming Leader. State: Replica: 64dbb5c83cfd4521aa222025e6c28095, State: Running, Role: LEADER
I20260812 06:17:07.436261 19712 sys_catalog.cc:565] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:17:07.436344 19717 consensus_queue.cc:237] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [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: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER }
I20260812 06:17:07.436751 19718 sys_catalog.cc:455] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "64dbb5c83cfd4521aa222025e6c28095" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER } }
I20260812 06:17:07.436794 19720 sys_catalog.cc:455] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 64dbb5c83cfd4521aa222025e6c28095. Latest consensus state: current_term: 1 leader_uuid: "64dbb5c83cfd4521aa222025e6c28095" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "64dbb5c83cfd4521aa222025e6c28095" member_type: VOTER } }
I20260812 06:17:07.436913 19718 sys_catalog.cc:458] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:07.436946 19720 sys_catalog.cc:458] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [sys.catalog]: This master's current role is: LEADER
I20260812 06:17:07.437412 19726 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:17:07.438248 19726 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:17:07.438438 19225 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:17:07.439973 19726 catalog_manager.cc:1383] Generated new cluster ID: 5e0f6cd4a56346109c81f5322dfac084
I20260812 06:17:07.440022 19726 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:17:07.473489 19726 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:17:07.474037 19726 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:17:07.488096 19726 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095: Generated new TSK 0
I20260812 06:17:07.488281 19726 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:17:07.502904 19225 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:17:07.504915 19744 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:17:07.504946 19745 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:17:07.504953 19225 server_base.cc:1061] running on GCE node
W20260812 06:17:07.504987 19753 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:17:07.505362 19225 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:17:07.505406 19225 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:17:07.505421 19225 hybrid_clock.cc:648] HybridClock initialized: now 1786515427505421 us; error 0 us; skew 500 ppm
I20260812 06:17:07.506238 19225 webserver.cc:533] Webserver started at http://127.18.198.65:35613/ using document root <none> and password file <none>
I20260812 06:17:07.506392 19225 fs_manager.cc:362] Metadata directory not provided
I20260812 06:17:07.506443 19225 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:17:07.506516 19225 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:17:07.506896 19225 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/instance:
uuid: "7713c6280e2846a0982c518bc88735cf"
format_stamp: "Formatted at 2026-08-12 06:17:07 on dist-test-slave-2j7r"
I20260812 06:17:07.508332 19225 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:17:07.509213 19769 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:17:07.509449 19225 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:17:07.509523 19225 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root
uuid: "7713c6280e2846a0982c518bc88735cf"
format_stamp: "Formatted at 2026-08-12 06:17:07 on dist-test-slave-2j7r"
I20260812 06:17:07.509595 19225 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-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:17:07.515399 19225 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:17:07.515661 19225 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:17:07.515894 19225 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:17:07.516304 19225 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:17:07.516338 19225 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:07.516371 19225 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:17:07.516397 19225 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:17:07.520280 19225 rpc_server.cc:307] RPC server started. Bound to: 127.18.198.65:43983
I20260812 06:17:07.520335 19889 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.18.198.65:43983 every 8 connection(s)
I20260812 06:17:07.527135 19892 heartbeater.cc:344] Connected to a master server at 127.18.198.126:35023
I20260812 06:17:07.527232 19892 heartbeater.cc:461] Registering TS with master...
I20260812 06:17:07.527455 19892 heartbeater.cc:507] Master 127.18.198.126:35023 requested a full tablet report, sending...
I20260812 06:17:07.528067 19651 ts_manager.cc:194] Registered new tserver with Master: 7713c6280e2846a0982c518bc88735cf (127.18.198.65:43983)
I20260812 06:17:07.528419 19225 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007741082s
I20260812 06:17:07.529018 19651 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:34622
I20260812 06:17:07.534768 19651 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:34628:
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:17:07.542729 19820 tablet_service.cc:1511] Processing CreateTablet for tablet 797d8eaacfda456780d06ab0bb8b0511 (DEFAULT_TABLE table=heavy-update-compaction-test [id=4d41e135fe4540b98f0850f36527b14d]), partition=
I20260812 06:17:07.542966 19820 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 797d8eaacfda456780d06ab0bb8b0511. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:17:07.544723 19920 tablet_bootstrap.cc:492] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Bootstrap starting.
I20260812 06:17:07.545594 19920 tablet_bootstrap.cc:654] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Neither blocks nor log segments found. Creating new log.
I20260812 06:17:07.546554 19920 tablet_bootstrap.cc:492] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: No bootstrap required, opened a new log
I20260812 06:17:07.546646 19920 ts_tablet_manager.cc:1403] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:17:07.547019 19920 raft_consensus.cc:359] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7713c6280e2846a0982c518bc88735cf" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 43983 } }
I20260812 06:17:07.547098 19920 raft_consensus.cc:385] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:17:07.547127 19920 raft_consensus.cc:740] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 7713c6280e2846a0982c518bc88735cf, State: Initialized, Role: FOLLOWER
I20260812 06:17:07.547225 19920 consensus_queue.cc:260] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [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: "7713c6280e2846a0982c518bc88735cf" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 43983 } }
I20260812 06:17:07.547284 19920 raft_consensus.cc:399] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:17:07.547312 19920 raft_consensus.cc:493] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:17:07.547344 19920 raft_consensus.cc:3060] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:17:07.548062 19920 raft_consensus.cc:515] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7713c6280e2846a0982c518bc88735cf" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 43983 } }
I20260812 06:17:07.548192 19920 leader_election.cc:304] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [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: 7713c6280e2846a0982c518bc88735cf; no voters: 
I20260812 06:17:07.548381 19920 leader_election.cc:290] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:17:07.548457 19923 raft_consensus.cc:2804] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:17:07.548650 19923 raft_consensus.cc:697] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 1 LEADER]: Becoming Leader. State: Replica: 7713c6280e2846a0982c518bc88735cf, State: Running, Role: LEADER
I20260812 06:17:07.548734 19892 heartbeater.cc:499] Master 127.18.198.126:35023 was elected leader, sending a full tablet report...
I20260812 06:17:07.548733 19920 ts_tablet_manager.cc:1434] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:17:07.548851 19923 consensus_queue.cc:237] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [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: "7713c6280e2846a0982c518bc88735cf" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 43983 } }
I20260812 06:17:07.550130 19651 catalog_manager.cc:5719] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf reported cstate change: term changed from 0 to 1, leader changed from <none> to 7713c6280e2846a0982c518bc88735cf (127.18.198.65). New cstate: current_term: 1 leader_uuid: "7713c6280e2846a0982c518bc88735cf" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "7713c6280e2846a0982c518bc88735cf" member_type: VOTER last_known_addr { host: "127.18.198.65" port: 43983 } health_report { overall_health: HEALTHY } } }
I20260812 06:17:07.600987 19225 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.012s	sys 0.010s
I20260812 06:17:07.771133 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511): perf score=23.023690
I20260812 06:17:07.949564 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.178s	user 0.116s	sys 0.058s Metrics: {"bytes_written":15999660,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":52,"dirs.run_cpu_time_us":180,"dirs.run_wall_time_us":900,"drs_written":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4,"lbm_write_time_us":45957,"lbm_writes_lt_1ms":957,"peak_mem_usage":0,"reinsert_count":0,"rows_written":106,"update_count":1950}
I20260812 06:17:07.950325 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling LogGCOp(797d8eaacfda456780d06ab0bb8b0511): free 20743880 bytes of WAL
I20260812 06:17:07.950551 19778 log_reader.cc:385] T 797d8eaacfda456780d06ab0bb8b0511: removed 2 log segments from log reader
I20260812 06:17:07.950596 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000001 (ops 1-6)
I20260812 06:17:07.950634 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000002 (ops 7-11)
I20260812 06:17:07.954205 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: LogGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.004s	user 0.000s	sys 0.003s Metrics: {}
I20260812 06:17:07.954609 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:07.975394 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.021s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5194,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.975834 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511): 20924073 bytes on disk
I20260812 06:17:07.976245 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":48,"lbm_reads_lt_1ms":4}
I20260812 06:17:07.976667 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:07.986109 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3473,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:07.986501 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:08.171182 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.184s	user 0.110s	sys 0.075s Metrics: {"cfile_cache_miss":623,"cfile_cache_miss_bytes":28548943,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":386,"lbm_read_time_us":13641,"lbm_reads_lt_1ms":659,"lbm_write_time_us":28340,"lbm_writes_lt_1ms":633,"peak_mem_usage":74091738,"reinsert_count":0,"spinlock_wait_cycles":11264,"thread_start_us":356,"threads_started":5,"update_count":2950}
I20260812 06:17:08.171783 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:08.221056 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.049s	user 0.024s	sys 0.020s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20485,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.221670 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:08.244206 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.022s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5264,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.244660 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:08.254053 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3496,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.254531 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:08.416199 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.161s	user 0.121s	sys 0.040s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959184,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":699,"lbm_read_time_us":11714,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34731,"lbm_writes_lt_1ms":643,"mutex_wait_us":30,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3200,"update_count":3000}
I20260812 06:17:08.416700 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:08.470408 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.054s	user 0.039s	sys 0.012s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":23894,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.471014 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:08.482422 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3981,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.482944 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:08.631500 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.148s	user 0.108s	sys 0.035s 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":553,"lbm_read_time_us":12160,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27488,"lbm_writes_lt_1ms":543,"mutex_wait_us":281,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":23552,"update_count":2500}
I20260812 06:17:08.632133 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:08.670032 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.038s	user 0.025s	sys 0.012s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":16952,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.670603 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:08.823783 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.153s	user 0.089s	sys 0.052s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20754122,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":199,"lbm_read_time_us":9314,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22817,"lbm_writes_lt_1ms":443,"mutex_wait_us":27,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":10112,"update_count":2000}
I20260812 06:17:08.824337 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:08.876258 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.052s	user 0.016s	sys 0.028s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21679,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:08.876798 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:08.891968 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5771,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:08.892398 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:09.077840 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.185s	user 0.121s	sys 0.059s 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":741,"lbm_read_time_us":13030,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30104,"lbm_writes_lt_1ms":543,"mutex_wait_us":23,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":30592,"update_count":2500}
I20260812 06:17:09.078366 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:09.129680 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.051s	user 0.035s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":24055,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:09.130250 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.147940 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.018s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5002,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.148826 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:09.189626 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.041s	user 0.024s	sys 0.004s Metrics: {"bytes_written":1275443,"cfile_init":1,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":256,"dirs.run_wall_time_us":1535,"drs_written":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1608,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":31,"spinlock_wait_cycles":13184}
I20260812 06:17:09.190276 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511): 482 bytes on disk
I20260812 06:17:09.190655 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4}
I20260812 06:17:09.191085 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=3.181125
I20260812 06:17:09.204974 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.014s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4512902,"delete_count":0,"lbm_write_time_us":4644,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:17:09.205466 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling LogGCOp(797d8eaacfda456780d06ab0bb8b0511): free 136728218 bytes of WAL
I20260812 06:17:09.205735 19778 log_reader.cc:385] T 797d8eaacfda456780d06ab0bb8b0511: removed 13 log segments from log reader
I20260812 06:17:09.205792 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000003 (ops 12-16)
I20260812 06:17:09.205842 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000004 (ops 17-21)
I20260812 06:17:09.205920 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000005 (ops 22-26)
I20260812 06:17:09.205972 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000006 (ops 27-31)
I20260812 06:17:09.205998 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000007 (ops 32-36)
I20260812 06:17:09.206030 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000008 (ops 37-41)
I20260812 06:17:09.206060 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000009 (ops 42-46)
I20260812 06:17:09.206092 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000010 (ops 47-51)
I20260812 06:17:09.206122 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000011 (ops 52-56)
I20260812 06:17:09.206146 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000012 (ops 57-61)
I20260812 06:17:09.206173 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000013 (ops 62-66)
I20260812 06:17:09.206236 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000014 (ops 67-71)
I20260812 06:17:09.206274 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000015 (ops 72-76)
I20260812 06:17:09.230489 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: LogGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.025s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:17:09.230887 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.247159 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.016s	user 0.001s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4190,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.247604 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.257207 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.001s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3611,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.257586 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:09.494599 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.237s	user 0.142s	sys 0.090s Metrics: {"cfile_cache_miss":835,"cfile_cache_miss_bytes":37164233,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":826,"lbm_read_time_us":17011,"lbm_reads_lt_1ms":875,"lbm_write_time_us":42817,"lbm_writes_lt_1ms":843,"mutex_wait_us":86,"peak_mem_usage":100395616,"reinsert_count":0,"spinlock_wait_cycles":2304,"thread_start_us":81,"threads_started":1,"update_count":4000}
I20260812 06:17:09.495114 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=18.063937
I20260812 06:17:09.545130 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.050s	user 0.030s	sys 0.020s Metrics: {"bytes_written":20512317,"delete_count":0,"lbm_write_time_us":21664,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:09.545887 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.563001 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.017s	user 0.009s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":6233,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.563431 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:09.738838 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.175s	user 0.111s	sys 0.064s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959068,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1067,"lbm_read_time_us":10674,"lbm_reads_lt_1ms":664,"lbm_write_time_us":33268,"lbm_writes_lt_1ms":643,"mutex_wait_us":48,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":8064,"update_count":3000}
I20260812 06:17:09.740089 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=15.087375
I20260812 06:17:09.800315 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.060s	user 0.028s	sys 0.029s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":29341,"lbm_writes_1-10_ms":3,"lbm_writes_lt_1ms":410,"reinsert_count":0,"update_count":2050}
I20260812 06:17:09.800772 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.820535 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.020s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5493,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:09.820990 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:09.830641 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.003s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3588,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:09.831051 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:10.010635 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.179s	user 0.140s	sys 0.039s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959174,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":643,"lbm_read_time_us":12477,"lbm_reads_lt_1ms":673,"lbm_write_time_us":37764,"lbm_writes_lt_1ms":643,"mutex_wait_us":59,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3968,"update_count":3000}
I20260812 06:17:10.011246 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=15.087375
I20260812 06:17:10.065339 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.054s	user 0.021s	sys 0.033s Metrics: {"bytes_written":16820145,"delete_count":0,"lbm_write_time_us":24430,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:10.065898 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:10.091602 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.026s	user 0.012s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5673,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.092037 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:10.101372 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3506,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.101780 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:10.257485 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.156s	user 0.123s	sys 0.032s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959174,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":889,"lbm_read_time_us":11112,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33438,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13440,"update_count":3000}
I20260812 06:17:10.257948 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:10.298947 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.041s	user 0.014s	sys 0.024s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":18046,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.299515 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:10.310410 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4203,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:10.310945 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:10.476147 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.165s	user 0.125s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24856650,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":177,"lbm_read_time_us":12421,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28890,"lbm_writes_lt_1ms":543,"mutex_wait_us":2,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":12928,"update_count":2500}
I20260812 06:17:10.476807 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:10.518646 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.042s	user 0.013s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18197,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:17:10.519143 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:10.548472 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1234478,"cfile_init":1,"dirs.queue_time_us":44,"dirs.run_cpu_time_us":172,"dirs.run_wall_time_us":1348,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1777,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:10.549225 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling LogGCOp(797d8eaacfda456780d06ab0bb8b0511): free 121006410 bytes of WAL
I20260812 06:17:10.549458 19778 log_reader.cc:385] T 797d8eaacfda456780d06ab0bb8b0511: removed 12 log segments from log reader
I20260812 06:17:10.549520 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000016 (ops 77-81)
I20260812 06:17:10.549587 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000017 (ops 82-86)
I20260812 06:17:10.549672 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000018 (ops 87-91)
I20260812 06:17:10.549712 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000019 (ops 92-96)
I20260812 06:17:10.549738 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000020 (ops 97-101)
I20260812 06:17:10.549796 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000021 (ops 102-106)
I20260812 06:17:10.549829 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000022 (ops 107-110)
I20260812 06:17:10.549850 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000023 (ops 111-115)
I20260812 06:17:10.549882 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000024 (ops 116-120)
I20260812 06:17:10.549904 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000025 (ops 121-125)
I20260812 06:17:10.549933 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000026 (ops 126-130)
I20260812 06:17:10.549961 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000027 (ops 131-135)
I20260812 06:17:10.574934 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: LogGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.026s	user 0.000s	sys 0.024s Metrics: {}
I20260812 06:17:10.575313 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=3.181125
I20260812 06:17:10.587297 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.012s	user 0.007s	sys 0.003s Metrics: {"bytes_written":5087239,"delete_count":0,"lbm_write_time_us":4635,"lbm_writes_lt_1ms":127,"reinsert_count":0,"update_count":620}
I20260812 06:17:10.587729 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.196750
I20260812 06:17:10.595273 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.007s	user 0.000s	sys 0.006s Metrics: {"bytes_written":3118055,"delete_count":0,"lbm_write_time_us":2700,"lbm_writes_lt_1ms":79,"reinsert_count":0,"update_count":380}
I20260812 06:17:10.595649 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511): 472 bytes on disk
I20260812 06:17:10.596083 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":65,"lbm_reads_lt_1ms":4}
I20260812 06:17:10.596717 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:10.787016 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.190s	user 0.123s	sys 0.064s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959160,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":181,"lbm_read_time_us":12402,"lbm_reads_lt_1ms":673,"lbm_write_time_us":31446,"lbm_writes_lt_1ms":643,"mutex_wait_us":2,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":2560,"thread_start_us":69,"threads_started":1,"update_count":3000}
I20260812 06:17:10.787551 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=16.079562
I20260812 06:17:10.843698 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.056s	user 0.020s	sys 0.028s Metrics: {"bytes_written":17763699,"delete_count":0,"lbm_write_time_us":22649,"lbm_writes_lt_1ms":436,"reinsert_count":0,"update_count":2165}
I20260812 06:17:10.844132 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.196750
I20260812 06:17:10.854074 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.010s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3159084,"delete_count":0,"lbm_write_time_us":2885,"lbm_writes_lt_1ms":80,"reinsert_count":0,"update_count":385}
I20260812 06:17:10.854506 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:10.864552 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.010s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3309,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:10.865341 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:11.087927 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.222s	user 0.126s	sys 0.085s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959153,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":564,"lbm_read_time_us":15841,"lbm_reads_lt_1ms":673,"lbm_write_time_us":34059,"lbm_writes_lt_1ms":643,"mutex_wait_us":65,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":39296,"update_count":3000}
I20260812 06:17:11.088539 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=18.063937
I20260812 06:17:11.150491 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.062s	user 0.035s	sys 0.016s Metrics: {"bytes_written":20512316,"delete_count":0,"lbm_write_time_us":23936,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:17:11.150976 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:11.161566 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3722,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:17:11.162053 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:11.351840 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.190s	user 0.109s	sys 0.076s 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":149,"lbm_read_time_us":12448,"lbm_reads_lt_1ms":672,"lbm_write_time_us":34600,"lbm_writes_lt_1ms":643,"mutex_wait_us":1,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":3000}
I20260812 06:17:11.352481 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=16.079562
I20260812 06:17:11.410360 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.058s	user 0.041s	sys 0.003s Metrics: {"bytes_written":17763701,"delete_count":0,"lbm_write_time_us":19457,"lbm_writes_lt_1ms":436,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2165}
I20260812 06:17:11.410847 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=5.165500
I20260812 06:17:11.427552 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.017s	user 0.014s	sys 0.000s Metrics: {"bytes_written":6851288,"delete_count":0,"lbm_write_time_us":6737,"lbm_writes_lt_1ms":170,"reinsert_count":0,"update_count":835}
I20260812 06:17:11.428133 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:11.611735 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.183s	user 0.111s	sys 0.068s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28959076,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":135,"lbm_read_time_us":11872,"lbm_reads_lt_1ms":672,"lbm_write_time_us":31542,"lbm_writes_lt_1ms":643,"mutex_wait_us":21,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9728,"update_count":3000}
I20260812 06:17:11.612347 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=16.079562
I20260812 06:17:11.660190 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.048s	user 0.031s	sys 0.008s Metrics: {"bytes_written":18379057,"delete_count":0,"lbm_write_time_us":18401,"lbm_writes_lt_1ms":451,"reinsert_count":0,"update_count":2240}
I20260812 06:17:11.660805 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.196750
I20260812 06:17:11.673394 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.012s	user 0.009s	sys 0.000s Metrics: {"bytes_written":2543709,"delete_count":0,"lbm_write_time_us":3492,"lbm_writes_lt_1ms":65,"reinsert_count":0,"update_count":310}
I20260812 06:17:11.673794 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:11.682503 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3278,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.682868 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:11.880090 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.197s	user 0.121s	sys 0.076s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28959136,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":162,"lbm_read_time_us":12680,"lbm_reads_lt_1ms":673,"lbm_write_time_us":33957,"lbm_writes_lt_1ms":643,"mutex_wait_us":20,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":11520,"update_count":3000}
I20260812 06:17:11.880590 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=14.095187
I20260812 06:17:11.932433 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.048s	user 0.026s	sys 0.019s Metrics: {"bytes_written":16820143,"delete_count":0,"lbm_write_time_us":21524,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:17:11.932865 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=2.188937
I20260812 06:17:11.942867 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3404,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:17:11.944128 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:11.975821 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushMRSOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234477,"cfile_init":1,"dirs.queue_time_us":59,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1314,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:17:11.976457 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling LogGCOp(797d8eaacfda456780d06ab0bb8b0511): free 124710644 bytes of WAL
I20260812 06:17:11.976670 19778 log_reader.cc:385] T 797d8eaacfda456780d06ab0bb8b0511: removed 12 log segments from log reader
I20260812 06:17:11.976718 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000028 (ops 136-140)
I20260812 06:17:11.976754 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000029 (ops 141-145)
I20260812 06:17:11.976787 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000030 (ops 146-150)
I20260812 06:17:11.976812 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000031 (ops 151-155)
I20260812 06:17:11.976842 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000032 (ops 156-160)
I20260812 06:17:11.976873 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000033 (ops 161-165)
I20260812 06:17:11.976904 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000034 (ops 166-170)
I20260812 06:17:11.976934 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000035 (ops 171-175)
I20260812 06:17:11.976966 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000036 (ops 176-180)
I20260812 06:17:11.976998 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000037 (ops 181-185)
I20260812 06:17:11.977030 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000038 (ops 186-190)
I20260812 06:17:11.977061 19778 log.cc:1079] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: Deleting log segment in path: /tmp/dist-test-taskpTEE0Z/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515422311025-19225-0/minicluster-data/ts-0-root/wals/797d8eaacfda456780d06ab0bb8b0511/wal-000000039 (ops 191-195)
I20260812 06:17:12.001392 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: LogGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.025s	user 0.000s	sys 0.025s Metrics: {}
I20260812 06:17:12.001760 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511): 473 bytes on disk
I20260812 06:17:12.002403 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: UndoDeltaBlockGCOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":68,"lbm_reads_lt_1ms":4}
I20260812 06:17:12.002959 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=3.181125
I20260812 06:17:12.017280 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.014s	user 0.013s	sys 0.001s Metrics: {"bytes_written":5251342,"delete_count":0,"lbm_write_time_us":5146,"lbm_writes_lt_1ms":131,"mutex_wait_us":617,"reinsert_count":0,"update_count":640}
I20260812 06:17:12.017628 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.196750
I20260812 06:17:12.028182 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: FlushDeltaMemStoresOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":2953955,"delete_count":0,"lbm_write_time_us":3939,"lbm_writes_lt_1ms":75,"reinsert_count":0,"update_count":360}
I20260812 06:17:12.028594 19898 maintenance_manager.cc:419] P 7713c6280e2846a0982c518bc88735cf: Scheduling MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511): perf score=1.000000
I20260812 06:17:12.061153 19225 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.460s	user 1.586s	sys 0.174s
I20260812 06:17:12.141752 19225 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.080s	user 0.003s	sys 0.000s
I20260812 06:17:12.142319 19225 tablet_server.cc:179] TabletServer@127.18.198.65:0 shutting down...
I20260812 06:17:12.214442 19778 maintenance_manager.cc:643] P 7713c6280e2846a0982c518bc88735cf: MajorDeltaCompactionOp(797d8eaacfda456780d06ab0bb8b0511) complete. Timing: real 0.186s	user 0.106s	sys 0.079s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33061676,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":571,"lbm_read_time_us":14472,"lbm_reads_lt_1ms":770,"lbm_write_time_us":32225,"lbm_writes_lt_1ms":743,"mutex_wait_us":71,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":74752,"thread_start_us":92,"threads_started":1,"update_count":3500}
I20260812 06:17:12.215811 19225 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:17:12.216120 19225 tablet_replica.cc:333] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf: stopping tablet replica
I20260812 06:17:12.216266 19225 raft_consensus.cc:2243] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:12.216431 19225 raft_consensus.cc:2272] T 797d8eaacfda456780d06ab0bb8b0511 P 7713c6280e2846a0982c518bc88735cf [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:12.220130 19225 tablet_server.cc:196] TabletServer@127.18.198.65:0 shutdown complete.
I20260812 06:17:12.271087 19225 master.cc:562] Master@127.18.198.126:35023 shutting down...
I20260812 06:17:12.273922 19225 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:17:12.274088 19225 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:17:12.274140 19225 tablet_replica.cc:333] T 00000000000000000000000000000000 P 64dbb5c83cfd4521aa222025e6c28095: stopping tablet replica
I20260812 06:17:12.286245 19225 master.cc:584] Master@127.18.198.126:35023 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4966 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10036 ms total)

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