[==========] Running 2 tests from 1 test suite.
[----------] Global test environment set-up.
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0
WARNING: Logging before InitGoogleLogging() is written to STDERR
I20260812 06:19:03.671161  7759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.147.254:34329
I20260812 06:19:03.672108  7759 env_posix.cc:2285] Not raising this process' open files per process limit of 1048576; it is already as high as it can go
I20260812 06:19:03.672652  7759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.678622  7776 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.678877  7759 server_base.cc:1061] running on GCE node
W20260812 06:19:03.678889  7769 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.679129  7768 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.679608  7759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.679694  7759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.679723  7759 hybrid_clock.cc:648] HybridClock initialized: now 1786515543679721 us; error 0 us; skew 500 ppm
I20260812 06:19:03.681320  7759 webserver.cc:533] Webserver started at http://127.7.147.254:35947/ using document root <none> and password file <none>
I20260812 06:19:03.681862  7759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.681924  7759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.682111  7759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.683677  7759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/master-0-root/instance:
uuid: "9ec4fa4fd2364d649945ba22ddc726e1"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-cvwc"
I20260812 06:19:03.686924  7759 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.004s	sys 0.000s
I20260812 06:19:03.688779  7783 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.689747  7759 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.003s	sys 0.000s
I20260812 06:19:03.689851  7759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/master-0-root
uuid: "9ec4fa4fd2364d649945ba22ddc726e1"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-cvwc"
I20260812 06:19:03.689944  7759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.720948  7759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.721606  7759 env_posix.cc:2285] Not raising this process' running threads per effective uid limit of 18446744073709551615; it is already as high as it can go
I20260812 06:19:03.721796  7759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.729296  7867 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.147.254:34329 every 8 connection(s)
I20260812 06:19:03.729305  7759 rpc_server.cc:307] RPC server started. Bound to: 127.7.147.254:34329
I20260812 06:19:03.731572  7868 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.736979  7868 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: Bootstrap starting.
I20260812 06:19:03.739291  7868 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.740252  7868 log.cc:826] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:03.741873  7868 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: No bootstrap required, opened a new log
I20260812 06:19:03.744583  7868 raft_consensus.cc:359] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER }
I20260812 06:19:03.744748  7868 raft_consensus.cc:385] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.744817  7868 raft_consensus.cc:740] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 9ec4fa4fd2364d649945ba22ddc726e1, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.745431  7868 consensus_queue.cc:260] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [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: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER }
I20260812 06:19:03.745579  7868 raft_consensus.cc:399] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.745646  7868 raft_consensus.cc:493] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.745783  7868 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.746536  7868 raft_consensus.cc:515] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER }
I20260812 06:19:03.746939  7868 leader_election.cc:304] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [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: 9ec4fa4fd2364d649945ba22ddc726e1; no voters: 
I20260812 06:19:03.747228  7868 leader_election.cc:290] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.747327  7871 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.747546  7871 raft_consensus.cc:697] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 1 LEADER]: Becoming Leader. State: Replica: 9ec4fa4fd2364d649945ba22ddc726e1, State: Running, Role: LEADER
I20260812 06:19:03.747946  7871 consensus_queue.cc:237] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [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: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER }
I20260812 06:19:03.748173  7868 sys_catalog.cc:565] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:03.749758  7872 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER } }
I20260812 06:19:03.749801  7876 sys_catalog.cc:455] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 9ec4fa4fd2364d649945ba22ddc726e1. Latest consensus state: current_term: 1 leader_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "9ec4fa4fd2364d649945ba22ddc726e1" member_type: VOTER } }
I20260812 06:19:03.749884  7872 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.749898  7876 sys_catalog.cc:458] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:03.750388  7759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
W20260812 06:19:03.752390  7900 catalog_manager.cc:1594] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: loading cluster ID for follower catalog manager: Not found: cluster ID entry not found
W20260812 06:19:03.752465  7900 catalog_manager.cc:883] Not found: cluster ID entry not found: failed to prepare follower catalog manager, will retry
I20260812 06:19:03.752522  7898 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:03.753183  7898 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:03.757543  7898 catalog_manager.cc:1383] Generated new cluster ID: 74abeec846b44f7e86ec87637c794f29
I20260812 06:19:03.757603  7898 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:03.766903  7898 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:03.767932  7898 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:03.777486  7898 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: Generated new TSK 0
I20260812 06:19:03.778192  7898 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:03.782917  7759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:03.785622  7905 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.785763  7759 server_base.cc:1061] running on GCE node
W20260812 06:19:03.785837  7904 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:03.785871  7908 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:03.786151  7759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:03.786195  7759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:03.786209  7759 hybrid_clock.cc:648] HybridClock initialized: now 1786515543786210 us; error 0 us; skew 500 ppm
I20260812 06:19:03.787070  7759 webserver.cc:533] Webserver started at http://127.7.147.193:42683/ using document root <none> and password file <none>
I20260812 06:19:03.787215  7759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:03.787267  7759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:03.787340  7759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:03.787681  7759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/instance:
uuid: "67f56eb23a6e43b6a3c7844ef813259d"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-cvwc"
I20260812 06:19:03.789085  7759 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:03.789979  7915 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.790197  7759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:03.790270  7759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root
uuid: "67f56eb23a6e43b6a3c7844ef813259d"
format_stamp: "Formatted at 2026-08-12 06:19:03 on dist-test-slave-cvwc"
I20260812 06:19:03.790342  7759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:03.801222  7759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:03.801586  7759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:03.802074  7759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:03.802893  7759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:03.802943  7759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.802994  7759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:03.803020  7759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:03.808929  7759 rpc_server.cc:307] RPC server started. Bound to: 127.7.147.193:33757
I20260812 06:19:03.808992  8027 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.147.193:33757 every 8 connection(s)
I20260812 06:19:03.821147  8028 heartbeater.cc:344] Connected to a master server at 127.7.147.254:34329
I20260812 06:19:03.821386  8028 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:03.821892  8028 heartbeater.cc:507] Master 127.7.147.254:34329 requested a full tablet report, sending...
I20260812 06:19:03.823307  7813 ts_manager.cc:194] Registered new tserver with Master: 67f56eb23a6e43b6a3c7844ef813259d (127.7.147.193:33757)
I20260812 06:19:03.823886  7759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.014339803s
I20260812 06:19:03.825428  7813 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:58656
I20260812 06:19:03.834534  7813 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:58666:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:03.849330  7969 tablet_service.cc:1511] Processing CreateTablet for tablet 02b00f43f313428ea9abdfa7665c8895 (DEFAULT_TABLE table=heavy-update-compaction-test [id=618a5d9e5ab34fbcb8aabffec417a1d4]), partition=
I20260812 06:19:03.849781  7969 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 02b00f43f313428ea9abdfa7665c8895. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:03.851922  8051 tablet_bootstrap.cc:492] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Bootstrap starting.
I20260812 06:19:03.852972  8051 tablet_bootstrap.cc:654] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:03.854010  8051 tablet_bootstrap.cc:492] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: No bootstrap required, opened a new log
I20260812 06:19:03.854104  8051 ts_tablet_manager.cc:1403] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Time spent bootstrapping tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:03.854507  8051 raft_consensus.cc:359] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67f56eb23a6e43b6a3c7844ef813259d" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 33757 } }
I20260812 06:19:03.854606  8051 raft_consensus.cc:385] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:03.854637  8051 raft_consensus.cc:740] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 67f56eb23a6e43b6a3c7844ef813259d, State: Initialized, Role: FOLLOWER
I20260812 06:19:03.854761  8051 consensus_queue.cc:260] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [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: "67f56eb23a6e43b6a3c7844ef813259d" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 33757 } }
I20260812 06:19:03.854848  8051 raft_consensus.cc:399] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:03.854892  8051 raft_consensus.cc:493] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:03.854939  8051 raft_consensus.cc:3060] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:03.855623  8051 raft_consensus.cc:515] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67f56eb23a6e43b6a3c7844ef813259d" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 33757 } }
I20260812 06:19:03.855752  8051 leader_election.cc:304] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [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: 67f56eb23a6e43b6a3c7844ef813259d; no voters: 
I20260812 06:19:03.855931  8051 leader_election.cc:290] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:03.856050  8053 raft_consensus.cc:2804] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:03.856252  8051 ts_tablet_manager.cc:1434] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Time spent starting tablet: real 0.002s	user 0.000s	sys 0.002s
I20260812 06:19:03.856287  8053 raft_consensus.cc:697] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 1 LEADER]: Becoming Leader. State: Replica: 67f56eb23a6e43b6a3c7844ef813259d, State: Running, Role: LEADER
I20260812 06:19:03.856637  8053 consensus_queue.cc:237] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [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: "67f56eb23a6e43b6a3c7844ef813259d" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 33757 } }
I20260812 06:19:03.856750  8028 heartbeater.cc:499] Master 127.7.147.254:34329 was elected leader, sending a full tablet report...
I20260812 06:19:03.859503  7813 catalog_manager.cc:5719] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d reported cstate change: term changed from 0 to 1, leader changed from <none> to 67f56eb23a6e43b6a3c7844ef813259d (127.7.147.193). New cstate: current_term: 1 leader_uuid: "67f56eb23a6e43b6a3c7844ef813259d" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "67f56eb23a6e43b6a3c7844ef813259d" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 33757 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:03.916958  7759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.053s	user 0.021s	sys 0.003s
I20260812 06:19:04.060016  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushMRSOp(02b00f43f313428ea9abdfa7665c8895): perf score=19.054940
I20260812 06:19:04.243355  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushMRSOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.183s	user 0.144s	sys 0.035s Metrics: {"bytes_written":15999661,"cfile_init":1,"compiler_manager_pool.queue_time_us":226,"delete_count":0,"dirs.queue_time_us":60,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":688,"drs_written":1,"lbm_read_time_us":71,"lbm_reads_lt_1ms":4,"lbm_write_time_us":44969,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"spinlock_wait_cycles":2432,"thread_start_us":115,"threads_started":1,"update_count":1950}
I20260812 06:19:04.244565  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling LogGCOp(02b00f43f313428ea9abdfa7665c8895): free 20743880 bytes of WAL
I20260812 06:19:04.244881  7925 log_reader.cc:385] T 02b00f43f313428ea9abdfa7665c8895: removed 2 log segments from log reader
I20260812 06:19:04.244956  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000001 (ops 1-6)
I20260812 06:19:04.245009  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000002 (ops 7-11)
I20260812 06:19:04.249472  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: LogGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.005s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:04.249927  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=5.165500
I20260812 06:19:04.271638  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.022s	user 0.007s	sys 0.013s Metrics: {"bytes_written":7261522,"delete_count":0,"lbm_write_time_us":8603,"lbm_writes_lt_1ms":180,"reinsert_count":0,"update_count":885}
I20260812 06:19:04.272209  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:04.441190  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.169s	user 0.118s	sys 0.048s Metrics: {"cfile_cache_miss":599,"cfile_cache_miss_bytes":27564300,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":975,"lbm_read_time_us":12967,"lbm_reads_lt_1ms":635,"lbm_write_time_us":30182,"lbm_writes_lt_1ms":610,"mutex_wait_us":134,"peak_mem_usage":71067165,"reinsert_count":0,"thread_start_us":322,"threads_started":5,"update_count":2835}
I20260812 06:19:04.441815  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=12.110812
I20260812 06:19:04.483027  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.041s	user 0.015s	sys 0.024s Metrics: {"bytes_written":13661292,"delete_count":0,"lbm_write_time_us":15544,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":335,"reinsert_count":0,"update_count":1665}
I20260812 06:19:04.483650  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:04.498329  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.014s	user 0.002s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3865,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.498790  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895): 16821651 bytes on disk
I20260812 06:19:04.499248  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":46,"lbm_reads_lt_1ms":4}
I20260812 06:19:04.499665  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:04.508581  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3203,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.509019  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:04.678180  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.169s	user 0.109s	sys 0.051s Metrics: {"cfile_cache_miss":556,"cfile_cache_miss_bytes":25759351,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":90,"lbm_read_time_us":11225,"lbm_reads_lt_1ms":596,"lbm_write_time_us":27494,"lbm_writes_lt_1ms":566,"mutex_wait_us":42,"peak_mem_usage":65100089,"reinsert_count":0,"spinlock_wait_cycles":4992,"update_count":2615}
I20260812 06:19:04.678716  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:04.736011  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.057s	user 0.025s	sys 0.030s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20260,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:04.736487  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:04.746887  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3817,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.747320  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:04.917685  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.170s	user 0.123s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":515,"lbm_read_time_us":10910,"lbm_reads_lt_1ms":572,"lbm_write_time_us":30151,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:04.918366  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=11.118625
I20260812 06:19:04.960333  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.042s	user 0.023s	sys 0.015s Metrics: {"bytes_written":12717755,"delete_count":0,"lbm_write_time_us":17165,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:04.960862  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:04.980593  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.020s	user 0.010s	sys 0.002s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4280,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:04.981005  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:04.990068  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.009s	user 0.001s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3343,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:04.990434  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.152951  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.162s	user 0.119s	sys 0.040s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815814,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":1084,"dirs.run_cpu_time_us":448,"dirs.run_wall_time_us":2433,"lbm_read_time_us":11285,"lbm_reads_lt_1ms":573,"lbm_write_time_us":25514,"lbm_writes_lt_1ms":543,"mutex_wait_us":78,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:05.153558  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=11.118625
I20260812 06:19:05.190089  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.036s	user 0.033s	sys 0.003s Metrics: {"bytes_written":12922847,"delete_count":0,"lbm_write_time_us":15108,"lbm_writes_lt_1ms":318,"reinsert_count":0,"update_count":1575}
I20260812 06:19:05.190663  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:05.215090  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.024s	user 0.010s	sys 0.001s Metrics: {"bytes_written":3487280,"delete_count":0,"lbm_write_time_us":4572,"lbm_writes_lt_1ms":88,"reinsert_count":0,"update_count":425}
I20260812 06:19:05.215551  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:05.231676  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.016s	user 0.005s	sys 0.009s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3564,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.232167  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.399255  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.167s	user 0.134s	sys 0.032s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815780,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":11035,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27654,"lbm_writes_lt_1ms":543,"mutex_wait_us":51,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":9088,"update_count":2500}
I20260812 06:19:05.399756  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:05.430905  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.031s	user 0.014s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13261,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.431435  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:05.445171  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.014s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5195,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.445701  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushMRSOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.473274  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushMRSOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":207,"dirs.run_wall_time_us":1186,"drs_written":1,"lbm_read_time_us":55,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1665,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:05.474143  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling LogGCOp(02b00f43f313428ea9abdfa7665c8895): free 124257251 bytes of WAL
I20260812 06:19:05.474383  7925 log_reader.cc:385] T 02b00f43f313428ea9abdfa7665c8895: removed 12 log segments from log reader
I20260812 06:19:05.474443  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000003 (ops 12-16)
I20260812 06:19:05.474490  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000004 (ops 17-21)
I20260812 06:19:05.474524  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000005 (ops 22-26)
I20260812 06:19:05.474546  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000006 (ops 27-31)
I20260812 06:19:05.474573  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000007 (ops 32-36)
I20260812 06:19:05.474598  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000008 (ops 37-41)
I20260812 06:19:05.474632  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000009 (ops 42-46)
I20260812 06:19:05.474661  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000010 (ops 47-50)
I20260812 06:19:05.474690  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000011 (ops 51-55)
I20260812 06:19:05.474715  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000012 (ops 56-60)
I20260812 06:19:05.474740  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000013 (ops 61-65)
I20260812 06:19:05.474771  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000014 (ops 66-70)
I20260812 06:19:05.499125  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: LogGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.025s	user 0.004s	sys 0.020s Metrics: {}
I20260812 06:19:05.499610  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895): 472 bytes on disk
I20260812 06:19:05.500105  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895) 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:19:05.500598  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=4.173312
I20260812 06:19:05.523852  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.023s	user 0.011s	sys 0.010s Metrics: {"bytes_written":6235918,"delete_count":0,"lbm_write_time_us":6831,"lbm_writes_lt_1ms":155,"reinsert_count":0,"update_count":760}
I20260812 06:19:05.524326  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.530624  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.006s	user 0.001s	sys 0.004s Metrics: {"bytes_written":1969352,"delete_count":0,"lbm_write_time_us":2012,"lbm_writes_lt_1ms":51,"reinsert_count":0,"update_count":240}
I20260812 06:19:05.531015  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.710903  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.180s	user 0.125s	sys 0.048s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918281,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":207,"lbm_read_time_us":12986,"lbm_reads_lt_1ms":674,"lbm_write_time_us":27721,"lbm_writes_lt_1ms":643,"mutex_wait_us":259,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:05.711362  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:05.770093  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.059s	user 0.031s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":19015,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:05.770596  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:05.780562  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3692,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.780977  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:05.937012  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.156s	user 0.116s	sys 0.040s 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":125,"lbm_read_time_us":10960,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26811,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:05.938104  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:05.971521  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.033s	user 0.019s	sys 0.013s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13921,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:05.972012  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:05.988794  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.017s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6332,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:05.989238  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.115206  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.126s	user 0.108s	sys 0.016s 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":856,"lbm_read_time_us":7788,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22568,"lbm_writes_lt_1ms":443,"mutex_wait_us":235,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":8448,"update_count":2000}
I20260812 06:19:06.115818  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:06.147434  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.031s	user 0.025s	sys 0.004s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12624,"lbm_writes_lt_1ms":303,"reinsert_count":0,"spinlock_wait_cycles":2432,"update_count":1500}
I20260812 06:19:06.147931  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:06.158420  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.010s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3900,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.158859  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.278179  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.119s	user 0.089s	sys 0.030s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":118,"lbm_read_time_us":9328,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21511,"lbm_writes_lt_1ms":443,"mutex_wait_us":41,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":384,"update_count":2000}
I20260812 06:19:06.278734  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:06.317029  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.038s	user 0.034s	sys 0.000s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15677,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.317507  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:06.327123  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3498,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.327533  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.436084  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.108s	user 0.091s	sys 0.018s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":7726,"lbm_reads_lt_1ms":472,"lbm_write_time_us":19883,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:06.438773  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:06.487645  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.049s	user 0.016s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12203,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.488117  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.625958  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.138s	user 0.094s	sys 0.044s Metrics: {"cfile_cache_miss":331,"cfile_cache_miss_bytes":16610741,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":38,"lbm_read_time_us":8320,"lbm_reads_lt_1ms":363,"lbm_write_time_us":23352,"lbm_writes_lt_1ms":343,"mutex_wait_us":22,"peak_mem_usage":38262756,"reinsert_count":0,"spinlock_wait_cycles":4864,"update_count":1500}
I20260812 06:19:06.626559  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:06.659200  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.032s	user 0.023s	sys 0.008s Metrics: {"bytes_written":12307493,"delete_count":0,"lbm_write_time_us":14061,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.659747  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:06.675855  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.016s	user 0.007s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6372,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.676332  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.791461  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.115s	user 0.104s	sys 0.011s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713275,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":142,"lbm_read_time_us":7110,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21578,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":13312,"update_count":2000}
I20260812 06:19:06.792053  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=10.126437
I20260812 06:19:06.832266  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.040s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":15142,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:06.832839  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:06.844132  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.011s	user 0.006s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4117,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:06.845054  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushMRSOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:06.877655  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushMRSOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":50,"dirs.run_cpu_time_us":128,"dirs.run_wall_time_us":1008,"drs_written":1,"lbm_read_time_us":62,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1912,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:06.878362  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling LogGCOp(02b00f43f313428ea9abdfa7665c8895): free 117302581 bytes of WAL
I20260812 06:19:06.878582  7925 log_reader.cc:385] T 02b00f43f313428ea9abdfa7665c8895: removed 12 log segments from log reader
I20260812 06:19:06.878628  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000015 (ops 71-75)
I20260812 06:19:06.878654  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000016 (ops 76-80)
I20260812 06:19:06.878680  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000017 (ops 81-85)
I20260812 06:19:06.878712  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000018 (ops 86-90)
I20260812 06:19:06.878750  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000019 (ops 91-95)
I20260812 06:19:06.878773  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000020 (ops 96-100)
I20260812 06:19:06.878806  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000021 (ops 101-104)
I20260812 06:19:06.878839  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000022 (ops 105-109)
I20260812 06:19:06.878870  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000023 (ops 110-114)
I20260812 06:19:06.878903  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000024 (ops 115-118)
I20260812 06:19:06.878935  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000025 (ops 119-123)
I20260812 06:19:06.878975  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000026 (ops 124-128)
I20260812 06:19:06.897953  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: LogGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.019s	user 0.001s	sys 0.019s Metrics: {}
I20260812 06:19:06.898392  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=3.181125
I20260812 06:19:06.915577  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.017s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4013,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:06.916036  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895): 462 bytes on disk
I20260812 06:19:06.916467  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895) 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:19:06.916955  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:06.931093  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.014s	user 0.008s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4974,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:06.931710  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:07.090950  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.159s	user 0.106s	sys 0.053s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918323,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":848,"lbm_read_time_us":11727,"lbm_reads_lt_1ms":674,"lbm_write_time_us":31476,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":13312,"thread_start_us":82,"threads_started":1,"update_count":3000}
I20260812 06:19:07.091589  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:07.142361  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.050s	user 0.030s	sys 0.019s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20894,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":402,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.142967  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:07.165578  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.022s	user 0.001s	sys 0.012s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6146,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.166082  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:07.180735  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.014s	user 0.011s	sys 0.001s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5155,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.181330  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:07.334219  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.153s	user 0.148s	sys 0.004s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918214,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":146,"lbm_read_time_us":9854,"lbm_reads_lt_1ms":673,"lbm_write_time_us":32359,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4480,"update_count":3000}
I20260812 06:19:07.334769  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:07.380456  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.045s	user 0.026s	sys 0.012s Metrics: {"bytes_written":16409898,"delete_count":0,"lbm_write_time_us":17186,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.380990  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:07.390846  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.010s	user 0.009s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3669,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.391260  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:07.543509  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.152s	user 0.114s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815679,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":893,"lbm_read_time_us":9472,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29203,"lbm_writes_lt_1ms":543,"mutex_wait_us":318,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2500}
I20260812 06:19:07.544123  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:07.590373  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.046s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18991,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.590826  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:07.736903  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.146s	user 0.114s	sys 0.025s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20713151,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":903,"lbm_read_time_us":9918,"lbm_reads_lt_1ms":463,"lbm_write_time_us":22655,"lbm_writes_lt_1ms":443,"mutex_wait_us":518,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2000}
I20260812 06:19:07.737542  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:07.782771  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.045s	user 0.028s	sys 0.015s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19326,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:07.783330  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:07.793627  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3508,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:07.794240  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:07.980901  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.186s	user 0.116s	sys 0.053s 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":489,"lbm_read_time_us":10136,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27226,"lbm_writes_lt_1ms":543,"mutex_wait_us":269,"peak_mem_usage":63115900,"reinsert_count":0,"update_count":2500}
I20260812 06:19:07.981734  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=14.095187
I20260812 06:19:08.030536  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.045s	user 0.023s	sys 0.016s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":16627,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:08.031087  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:08.046599  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.015s	user 0.006s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5684,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.047216  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:08.191193  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.144s	user 0.108s	sys 0.026s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815686,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1067,"lbm_read_time_us":9351,"lbm_reads_lt_1ms":572,"lbm_write_time_us":24918,"lbm_writes_lt_1ms":543,"mutex_wait_us":241,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:08.191886  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=11.118625
I20260812 06:19:08.231560  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.039s	user 0.016s	sys 0.021s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":16130,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:08.232070  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:08.253124  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.021s	user 0.004s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5115,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:08.253695  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:08.262356  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.008s	user 0.007s	sys 0.001s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3060,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.262769  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushMRSOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:08.290956  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushMRSOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.028s	user 0.026s	sys 0.000s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":49,"dirs.run_cpu_time_us":209,"dirs.run_wall_time_us":1144,"drs_written":1,"lbm_read_time_us":43,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1366,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:08.291659  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling LogGCOp(02b00f43f313428ea9abdfa7665c8895): free 136728509 bytes of WAL
I20260812 06:19:08.291893  7925 log_reader.cc:385] T 02b00f43f313428ea9abdfa7665c8895: removed 13 log segments from log reader
I20260812 06:19:08.291952  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000027 (ops 129-133)
I20260812 06:19:08.291996  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000028 (ops 134-138)
I20260812 06:19:08.292025  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000029 (ops 139-143)
I20260812 06:19:08.292057  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000030 (ops 144-148)
I20260812 06:19:08.292085  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000031 (ops 149-153)
I20260812 06:19:08.292117  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000032 (ops 154-158)
I20260812 06:19:08.292147  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000033 (ops 159-163)
I20260812 06:19:08.292172  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000034 (ops 164-168)
I20260812 06:19:08.292200  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000035 (ops 169-173)
I20260812 06:19:08.292228  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000036 (ops 174-178)
I20260812 06:19:08.292260  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000037 (ops 179-183)
I20260812 06:19:08.292290  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000038 (ops 184-188)
I20260812 06:19:08.292315  7925 log.cc:1079] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/02b00f43f313428ea9abdfa7665c8895/wal-000000039 (ops 189-193)
I20260812 06:19:08.318552  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: LogGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.027s	user 0.000s	sys 0.026s Metrics: {}
I20260812 06:19:08.318917  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895): 493 bytes on disk
I20260812 06:19:08.319300  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: UndoDeltaBlockGCOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":49,"lbm_reads_lt_1ms":4}
I20260812 06:19:08.319795  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=3.181125
I20260812 06:19:08.339535  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.020s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":4044,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:08.339953  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=2.188937
I20260812 06:19:08.353739  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.014s	user 0.000s	sys 0.011s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":5258,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:08.354198  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895): perf score=1.000000
I20260812 06:19:08.452220  7759 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.535s	user 1.665s	sys 0.147s
I20260812 06:19:08.541706  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: MajorDeltaCompactionOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.187s	user 0.110s	sys 0.077s Metrics: {"cfile_cache_miss":735,"cfile_cache_miss_bytes":33020843,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":5,"delta_iterators_relevant":5,"dirs.queue_time_us":537,"lbm_read_time_us":13916,"lbm_reads_lt_1ms":771,"lbm_write_time_us":30767,"lbm_writes_lt_1ms":743,"mutex_wait_us":19,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":11008,"thread_start_us":75,"threads_started":1,"update_count":3500}
I20260812 06:19:08.543339  8029 maintenance_manager.cc:419] P 67f56eb23a6e43b6a3c7844ef813259d: Scheduling FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895): perf score=6.157687
I20260812 06:19:08.545817  7759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.093s	user 0.004s	sys 0.000s
I20260812 06:19:08.546383  7759 tablet_server.cc:179] TabletServer@127.7.147.193:0 shutting down...
I20260812 06:19:08.565244  7925 maintenance_manager.cc:643] P 67f56eb23a6e43b6a3c7844ef813259d: FlushDeltaMemStoresOp(02b00f43f313428ea9abdfa7665c8895) complete. Timing: real 0.022s	user 0.016s	sys 0.003s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":7900,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:08.565829  7759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:08.566183  7759 tablet_replica.cc:333] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d: stopping tablet replica
I20260812 06:19:08.566386  7759 raft_consensus.cc:2243] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.566612  7759 raft_consensus.cc:2272] T 02b00f43f313428ea9abdfa7665c8895 P 67f56eb23a6e43b6a3c7844ef813259d [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.581310  7759 tablet_server.cc:196] TabletServer@127.7.147.193:0 shutdown complete.
I20260812 06:19:08.599439  7759 master.cc:562] Master@127.7.147.254:34329 shutting down...
I20260812 06:19:08.602555  7759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:08.602711  7759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:08.602787  7759 tablet_replica.cc:333] T 00000000000000000000000000000000 P 9ec4fa4fd2364d649945ba22ddc726e1: stopping tablet replica
I20260812 06:19:08.614941  7759 master.cc:584] Master@127.7.147.254:34329 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5010 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:08.691450  7759 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.7.147.254:36871
I20260812 06:19:08.691833  7759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:08.693670  8079 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:08.693805  8084 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:08.693879  7759 server_base.cc:1061] running on GCE node
W20260812 06:19:08.693904  8088 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:08.694108  7759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.694150  7759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:08.694164  7759 hybrid_clock.cc:648] HybridClock initialized: now 1786515548694164 us; error 0 us; skew 500 ppm
I20260812 06:19:08.694887  7759 webserver.cc:533] Webserver started at http://127.7.147.254:45029/ using document root <none> and password file <none>
I20260812 06:19:08.695032  7759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.695079  7759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.695154  7759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.695533  7759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/master-0-root/instance:
uuid: "87f6fdd7d3614066a544616e580be16f"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-cvwc"
I20260812 06:19:08.696964  7759 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:08.697870  8095 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.698086  7759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:08.698153  7759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/master-0-root
uuid: "87f6fdd7d3614066a544616e580be16f"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-cvwc"
I20260812 06:19:08.698222  7759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/master-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:08.707517  7759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.707818  7759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.711596  7759 rpc_server.cc:307] RPC server started. Bound to: 127.7.147.254:36871
I20260812 06:19:08.716579  8179 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.147.254:36871 every 8 connection(s)
I20260812 06:19:08.717031  8180 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 00000000000000000000000000000000. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:08.718825  8180 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f: Bootstrap starting.
I20260812 06:19:08.719568  8180 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.720491  8180 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f: No bootstrap required, opened a new log
I20260812 06:19:08.720865  8180 raft_consensus.cc:359] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER }
I20260812 06:19:08.720952  8180 raft_consensus.cc:385] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.720988  8180 raft_consensus.cc:740] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 87f6fdd7d3614066a544616e580be16f, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.721124  8180 consensus_queue.cc:260] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [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: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER }
I20260812 06:19:08.721194  8180 raft_consensus.cc:399] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.721230  8180 raft_consensus.cc:493] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.721279  8180 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.721980  8180 raft_consensus.cc:515] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER }
I20260812 06:19:08.722097  8180 leader_election.cc:304] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [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: 87f6fdd7d3614066a544616e580be16f; no voters: 
I20260812 06:19:08.722272  8180 leader_election.cc:290] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.722402  8185 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.722579  8185 raft_consensus.cc:697] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 1 LEADER]: Becoming Leader. State: Replica: 87f6fdd7d3614066a544616e580be16f, State: Running, Role: LEADER
I20260812 06:19:08.722673  8180 sys_catalog.cc:565] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:08.722702  8185 consensus_queue.cc:237] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [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: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER }
I20260812 06:19:08.723094  8187 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [sys.catalog]: SysCatalogTable state changed. Reason: New leader 87f6fdd7d3614066a544616e580be16f. Latest consensus state: current_term: 1 leader_uuid: "87f6fdd7d3614066a544616e580be16f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER } }
I20260812 06:19:08.723186  8187 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.723083  8186 sys_catalog.cc:455] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "87f6fdd7d3614066a544616e580be16f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "87f6fdd7d3614066a544616e580be16f" member_type: VOTER } }
I20260812 06:19:08.723238  8186 sys_catalog.cc:458] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:08.723439  8194 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:08.724205  8194 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:08.724414  7759 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:08.725876  8194 catalog_manager.cc:1383] Generated new cluster ID: d86213fee66e4a3dab7d9b80dc161951
I20260812 06:19:08.725922  8194 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:08.747774  8194 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:08.748324  8194 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:08.758621  8194 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f: Generated new TSK 0
I20260812 06:19:08.758795  8194 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:08.788924  7759 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:08.790951  8216 instance_detector.cc:116] could not retrieve Azure instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:08.791082  8218 instance_detector.cc:116] could not retrieve OpenStack instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
W20260812 06:19:08.791157  8215 instance_detector.cc:116] could not retrieve AWS instance metadata: Network error: curl error: HTTP response code said error: The requested URL returned error: 404
I20260812 06:19:08.791316  7759 server_base.cc:1061] running on GCE node
I20260812 06:19:08.791476  7759 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:08.791515  7759 system_unsync_time.cc:38] NTP support is disabled. Clock error bounds will not be accurate. This configuration is not suitable for distributed clusters.
I20260812 06:19:08.791529  7759 hybrid_clock.cc:648] HybridClock initialized: now 1786515548791529 us; error 0 us; skew 500 ppm
I20260812 06:19:08.792342  7759 webserver.cc:533] Webserver started at http://127.7.147.193:33945/ using document root <none> and password file <none>
I20260812 06:19:08.792481  7759 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:08.792531  7759 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:08.792594  7759 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:08.792935  7759 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/instance:
uuid: "2c87708121e045058a68f8dbd31a77ad"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-cvwc"
I20260812 06:19:08.794426  7759 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.002s	sys 0.000s
I20260812 06:19:08.795274  8225 log_block_manager.cc:4127] Time spent loading block containers with low live blocks: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.795480  7759 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:08.795542  7759 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root
uuid: "2c87708121e045058a68f8dbd31a77ad"
format_stamp: "Formatted at 2026-08-12 06:19:08 on dist-test-slave-cvwc"
I20260812 06:19:08.795598  7759 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/data
Total live blocks: 0
Total live bytes: 0
Total live bytes (after alignment): 0
Total number of LBM containers: 0 (0 full)
Did not check for missing blocks
Did not check for orphaned blocks
Total full LBM containers with extra space: 0 (0 repaired)
Total full LBM container extra space in bytes: 0 (0 repaired)
Total incomplete LBM containers: 0 (0 repaired)
Total LBM partial records: 0 (0 repaired)
Total corrupted LBM metadata records in RocksDB: 0 (0 repaired)
I20260812 06:19:08.818207  7759 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:08.818529  7759 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:08.818782  7759 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:08.819245  7759 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:08.819283  7759 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.819316  7759 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:08.819343  7759 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:08.823261  7759 rpc_server.cc:307] RPC server started. Bound to: 127.7.147.193:32789
I20260812 06:19:08.823688  8335 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.7.147.193:32789 every 8 connection(s)
I20260812 06:19:08.830083  8336 heartbeater.cc:344] Connected to a master server at 127.7.147.254:36871
I20260812 06:19:08.830174  8336 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:08.830358  8336 heartbeater.cc:507] Master 127.7.147.254:36871 requested a full tablet report, sending...
I20260812 06:19:08.830893  8120 ts_manager.cc:194] Registered new tserver with Master: 2c87708121e045058a68f8dbd31a77ad (127.7.147.193:32789)
I20260812 06:19:08.831382  7759 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.007633008s
I20260812 06:19:08.831658  8120 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:41446
I20260812 06:19:08.837890  8120 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:41452:
name: "heavy-update-compaction-test"
schema {
  columns {
    name: "key"
    type: INT64
    is_key: true
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_a"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_b"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_c"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_d"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
  columns {
    name: "val_e"
    type: STRING
    is_key: false
    is_nullable: false
    encoding: AUTO_ENCODING
    compression: DEFAULT_COMPRESSION
    cfile_block_size: 0
    immutable: false
  }
}
num_replicas: 1
split_rows_range_bounds {
}
partition_schema {
  range_schema {
  }
}
I20260812 06:19:08.847225  8271 tablet_service.cc:1511] Processing CreateTablet for tablet 6c7d5b18e45548fc94455536f68889b0 (DEFAULT_TABLE table=heavy-update-compaction-test [id=1f10469393434f4a899d1f538228a7e5]), partition=
I20260812 06:19:08.847527  8271 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 6c7d5b18e45548fc94455536f68889b0. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:08.850026  8355 tablet_bootstrap.cc:492] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Bootstrap starting.
I20260812 06:19:08.851044  8355 tablet_bootstrap.cc:654] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:08.852349  8355 tablet_bootstrap.cc:492] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: No bootstrap required, opened a new log
I20260812 06:19:08.852492  8355 ts_tablet_manager.cc:1403] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:08.852990  8355 raft_consensus.cc:359] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c87708121e045058a68f8dbd31a77ad" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 32789 } }
I20260812 06:19:08.853093  8355 raft_consensus.cc:385] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:08.853138  8355 raft_consensus.cc:740] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 2c87708121e045058a68f8dbd31a77ad, State: Initialized, Role: FOLLOWER
I20260812 06:19:08.853266  8355 consensus_queue.cc:260] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [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: "2c87708121e045058a68f8dbd31a77ad" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 32789 } }
I20260812 06:19:08.853356  8355 raft_consensus.cc:399] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:08.853399  8355 raft_consensus.cc:493] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:08.853440  8355 raft_consensus.cc:3060] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:08.854292  8355 raft_consensus.cc:515] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c87708121e045058a68f8dbd31a77ad" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 32789 } }
I20260812 06:19:08.854417  8355 leader_election.cc:304] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [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: 2c87708121e045058a68f8dbd31a77ad; no voters: 
I20260812 06:19:08.854602  8355 leader_election.cc:290] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:08.854712  8359 raft_consensus.cc:2804] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:08.854910  8336 heartbeater.cc:499] Master 127.7.147.254:36871 was elected leader, sending a full tablet report...
I20260812 06:19:08.854892  8355 ts_tablet_manager.cc:1434] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:08.854948  8359 raft_consensus.cc:697] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 1 LEADER]: Becoming Leader. State: Replica: 2c87708121e045058a68f8dbd31a77ad, State: Running, Role: LEADER
I20260812 06:19:08.855080  8359 consensus_queue.cc:237] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [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: "2c87708121e045058a68f8dbd31a77ad" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 32789 } }
I20260812 06:19:08.856365  8120 catalog_manager.cc:5719] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad reported cstate change: term changed from 0 to 1, leader changed from <none> to 2c87708121e045058a68f8dbd31a77ad (127.7.147.193). New cstate: current_term: 1 leader_uuid: "2c87708121e045058a68f8dbd31a77ad" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "2c87708121e045058a68f8dbd31a77ad" member_type: VOTER last_known_addr { host: "127.7.147.193" port: 32789 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:08.908371  7759 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.048s	user 0.009s	sys 0.012s
I20260812 06:19:09.074213  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushMRSOp(6c7d5b18e45548fc94455536f68889b0): perf score=23.023690
I20260812 06:19:09.231643  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushMRSOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.157s	user 0.123s	sys 0.032s Metrics: {"bytes_written":12307490,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":65,"dirs.run_cpu_time_us":186,"dirs.run_wall_time_us":715,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":40231,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:09.232383  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling LogGCOp(6c7d5b18e45548fc94455536f68889b0): free 20290830 bytes of WAL
I20260812 06:19:09.232617  8233 log_reader.cc:385] T 6c7d5b18e45548fc94455536f68889b0: removed 2 log segments from log reader
I20260812 06:19:09.232673  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000001 (ops 1-6)
I20260812 06:19:09.232710  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000002 (ops 7-10)
I20260812 06:19:09.236218  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: LogGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:09.236541  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0): 20513815 bytes on disk
I20260812 06:19:09.236940  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":60,"lbm_reads_lt_1ms":4}
I20260812 06:19:09.237335  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:09.253844  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.016s	user 0.007s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3659,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.254220  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:09.263751  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3454,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.264185  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:09.428320  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.164s	user 0.096s	sys 0.060s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24815802,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":433,"lbm_read_time_us":11971,"lbm_reads_lt_1ms":569,"lbm_write_time_us":27301,"lbm_writes_lt_1ms":543,"mutex_wait_us":35,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6144,"thread_start_us":300,"threads_started":5,"update_count":2500}
I20260812 06:19:09.428848  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:09.476660  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.048s	user 0.020s	sys 0.021s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18596,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:09.477146  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:09.492075  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.015s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5340,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:09.492626  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:09.645896  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.153s	user 0.109s	sys 0.040s 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":318,"lbm_read_time_us":11206,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26515,"lbm_writes_lt_1ms":543,"mutex_wait_us":77,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20480,"update_count":2500}
I20260812 06:19:09.646575  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=12.110812
I20260812 06:19:09.684998  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.038s	user 0.034s	sys 0.001s Metrics: {"bytes_written":13538208,"delete_count":0,"lbm_write_time_us":16536,"lbm_writes_lt_1ms":333,"reinsert_count":0,"update_count":1650}
I20260812 06:19:09.685467  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.196750
I20260812 06:19:09.693368  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.008s	user 0.003s	sys 0.003s Metrics: {"bytes_written":2871905,"delete_count":0,"lbm_write_time_us":2631,"lbm_writes_lt_1ms":73,"reinsert_count":0,"update_count":350}
I20260812 06:19:09.693753  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:09.826960  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.133s	user 0.105s	sys 0.026s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713236,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":139,"lbm_read_time_us":8652,"lbm_reads_lt_1ms":468,"lbm_write_time_us":23113,"lbm_writes_lt_1ms":443,"mutex_wait_us":24,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:09.827476  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=11.118625
I20260812 06:19:09.857317  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.030s	user 0.021s	sys 0.005s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12340,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:09.858045  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:09.872267  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.014s	user 0.006s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4230,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:09.872752  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:09.997121  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.124s	user 0.084s	sys 0.040s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713263,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":233,"lbm_read_time_us":7887,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21665,"lbm_writes_lt_1ms":443,"mutex_wait_us":40,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":9856,"update_count":2000}
I20260812 06:19:09.997915  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=10.126437
I20260812 06:19:10.033210  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.035s	user 0.022s	sys 0.005s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":12632,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.033809  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:10.043924  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3607,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.044561  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:10.156940  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.112s	user 0.096s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713272,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":397,"lbm_read_time_us":7429,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20969,"lbm_writes_lt_1ms":443,"mutex_wait_us":57,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":26368,"update_count":2000}
I20260812 06:19:10.157593  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=10.126437
I20260812 06:19:10.196056  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.038s	user 0.022s	sys 0.014s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16219,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.196607  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:10.206789  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3552,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.207229  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:10.323676  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.116s	user 0.079s	sys 0.037s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713274,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":145,"lbm_read_time_us":6963,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22916,"lbm_writes_lt_1ms":443,"mutex_wait_us":37,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":25856,"update_count":2000}
I20260812 06:19:10.324229  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=10.126437
I20260812 06:19:10.368033  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.044s	user 0.008s	sys 0.027s Metrics: {"bytes_written":12307489,"delete_count":0,"lbm_write_time_us":12001,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:10.368687  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:10.384325  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5910,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.384965  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushMRSOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:10.420001  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushMRSOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.035s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1234473,"cfile_init":1,"dirs.queue_time_us":69,"dirs.run_cpu_time_us":179,"dirs.run_wall_time_us":1140,"drs_written":1,"lbm_read_time_us":135,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1940,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:10.420608  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling LogGCOp(6c7d5b18e45548fc94455536f68889b0): free 124710293 bytes of WAL
I20260812 06:19:10.420828  8233 log_reader.cc:385] T 6c7d5b18e45548fc94455536f68889b0: removed 12 log segments from log reader
I20260812 06:19:10.420872  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000003 (ops 11-15)
I20260812 06:19:10.420899  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000004 (ops 16-20)
I20260812 06:19:10.420931  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000005 (ops 21-25)
I20260812 06:19:10.420964  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000006 (ops 26-30)
I20260812 06:19:10.420987  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000007 (ops 31-35)
I20260812 06:19:10.421018  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000008 (ops 36-40)
I20260812 06:19:10.421049  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000009 (ops 41-45)
I20260812 06:19:10.421082  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000010 (ops 46-50)
I20260812 06:19:10.421113  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000011 (ops 51-55)
I20260812 06:19:10.421144  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000012 (ops 56-60)
I20260812 06:19:10.421173  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000013 (ops 61-65)
I20260812 06:19:10.421204  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000014 (ops 66-70)
I20260812 06:19:10.440877  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: LogGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:19:10.441287  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0): 472 bytes on disk
I20260812 06:19:10.441699  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":53,"lbm_reads_lt_1ms":4}
I20260812 06:19:10.442222  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:10.464880  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.023s	user 0.008s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4872,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.465306  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:10.474828  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3413,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:10.475423  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:10.677670  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.202s	user 0.129s	sys 0.073s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918333,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":592,"lbm_read_time_us":12507,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34771,"lbm_writes_lt_1ms":643,"mutex_wait_us":52,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":3072,"thread_start_us":84,"threads_started":1,"update_count":3000}
I20260812 06:19:10.678920  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=15.087375
I20260812 06:19:10.753834  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.075s	user 0.021s	sys 0.039s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":27214,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":411,"reinsert_count":0,"update_count":2050}
I20260812 06:19:10.754316  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=6.157687
I20260812 06:19:10.779484  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.025s	user 0.009s	sys 0.009s Metrics: {"bytes_written":7794836,"delete_count":0,"lbm_write_time_us":7737,"lbm_writes_lt_1ms":193,"reinsert_count":0,"update_count":950}
I20260812 06:19:10.779945  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:10.968211  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.188s	user 0.117s	sys 0.062s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918095,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":571,"lbm_read_time_us":12419,"lbm_reads_lt_1ms":664,"lbm_write_time_us":30434,"lbm_writes_lt_1ms":643,"mutex_wait_us":266,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":12800,"update_count":3000}
I20260812 06:19:10.968765  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=18.063937
I20260812 06:19:11.028079  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.059s	user 0.028s	sys 0.019s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":22043,"lbm_writes_lt_1ms":503,"reinsert_count":0,"update_count":2500}
I20260812 06:19:11.028575  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.038895  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.010s	user 0.000s	sys 0.010s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3671,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.039568  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:11.217459  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.178s	user 0.107s	sys 0.070s Metrics: {"cfile_cache_miss":632,"cfile_cache_miss_bytes":28918097,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1033,"lbm_read_time_us":11726,"lbm_reads_lt_1ms":672,"lbm_write_time_us":28172,"lbm_writes_lt_1ms":643,"mutex_wait_us":481,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":6912,"update_count":3000}
I20260812 06:19:11.218034  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:11.255940  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.038s	user 0.024s	sys 0.011s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":15609,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.256465  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.278327  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.022s	user 0.013s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6113,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":102,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.278827  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.288429  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3603,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.288837  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:11.475819  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.187s	user 0.123s	sys 0.063s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918216,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":137,"lbm_read_time_us":13236,"lbm_reads_lt_1ms":673,"lbm_write_time_us":29415,"lbm_writes_lt_1ms":643,"mutex_wait_us":36,"peak_mem_usage":75542472,"reinsert_count":0,"update_count":3000}
I20260812 06:19:11.476415  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:11.519430  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.043s	user 0.033s	sys 0.007s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":18262,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.519973  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.534190  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.014s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5370,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.534657  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:11.696774  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.162s	user 0.108s	sys 0.049s 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":157,"lbm_read_time_us":10776,"lbm_reads_lt_1ms":572,"lbm_write_time_us":23511,"lbm_writes_lt_1ms":543,"mutex_wait_us":33,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":3584,"update_count":2500}
I20260812 06:19:11.697336  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:11.753459  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.056s	user 0.030s	sys 0.016s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":20070,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:11.753994  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.769182  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5798,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:11.773195  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushMRSOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:11.804175  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushMRSOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.031s	user 0.029s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":61,"dirs.run_cpu_time_us":227,"dirs.run_wall_time_us":1266,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1456,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:11.804793  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling LogGCOp(6c7d5b18e45548fc94455536f68889b0): free 121006436 bytes of WAL
I20260812 06:19:11.805009  8233 log_reader.cc:385] T 6c7d5b18e45548fc94455536f68889b0: removed 12 log segments from log reader
I20260812 06:19:11.805053  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000015 (ops 71-75)
I20260812 06:19:11.805083  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000016 (ops 76-80)
I20260812 06:19:11.805115  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000017 (ops 81-85)
I20260812 06:19:11.805148  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000018 (ops 86-90)
I20260812 06:19:11.805181  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000019 (ops 91-95)
I20260812 06:19:11.805213  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000020 (ops 96-100)
I20260812 06:19:11.805246  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000021 (ops 101-104)
I20260812 06:19:11.805279  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000022 (ops 105-109)
I20260812 06:19:11.805312  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000023 (ops 110-114)
I20260812 06:19:11.805346  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000024 (ops 115-119)
I20260812 06:19:11.805377  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000025 (ops 120-124)
I20260812 06:19:11.805409  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000026 (ops 125-129)
I20260812 06:19:11.825394  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: LogGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.020s	user 0.000s	sys 0.017s Metrics: {}
I20260812 06:19:11.825870  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0): 472 bytes on disk
I20260812 06:19:11.826319  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":61,"lbm_reads_lt_1ms":4}
I20260812 06:19:11.826831  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=3.181125
I20260812 06:19:11.847051  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.020s	user 0.006s	sys 0.010s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6534,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:11.847460  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:11.856282  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3192,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:11.856676  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:12.077962  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.221s	user 0.173s	sys 0.039s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020733,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":681,"lbm_read_time_us":15708,"lbm_reads_lt_1ms":774,"lbm_write_time_us":35555,"lbm_writes_lt_1ms":743,"mutex_wait_us":65,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":10240,"thread_start_us":72,"threads_started":1,"update_count":3500}
I20260812 06:19:12.078526  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=18.063937
I20260812 06:19:12.147178  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.068s	user 0.043s	sys 0.023s Metrics: {"bytes_written":20512315,"delete_count":0,"lbm_write_time_us":32756,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":501,"reinsert_count":0,"update_count":2500}
I20260812 06:19:12.147625  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=3.181125
I20260812 06:19:12.166692  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.019s	user 0.005s	sys 0.005s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4018,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:12.167184  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:12.175957  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3083,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:12.176366  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:12.350488  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.174s	user 0.144s	sys 0.030s Metrics: {"cfile_cache_miss":733,"cfile_cache_miss_bytes":33020615,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":268,"lbm_read_time_us":12200,"lbm_reads_lt_1ms":773,"lbm_write_time_us":35701,"lbm_writes_lt_1ms":743,"mutex_wait_us":26,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":8192,"update_count":3500}
I20260812 06:19:12.351034  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:12.391601  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.040s	user 0.029s	sys 0.009s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":17089,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.392174  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:12.412249  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.020s	user 0.006s	sys 0.007s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5920,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.412832  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:12.544968  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.132s	user 0.102s	sys 0.025s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815685,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":240,"lbm_read_time_us":9545,"lbm_reads_lt_1ms":564,"lbm_write_time_us":23996,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4352,"update_count":2500}
I20260812 06:19:12.545567  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:12.592425  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.047s	user 0.033s	sys 0.004s Metrics: {"bytes_written":16409899,"delete_count":0,"lbm_write_time_us":17455,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.592939  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:12.603351  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3644,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.604146  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:12.765653  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.161s	user 0.111s	sys 0.044s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815681,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":204,"lbm_read_time_us":8986,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27572,"lbm_writes_lt_1ms":543,"mutex_wait_us":28,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":109184,"update_count":2500}
I20260812 06:19:12.766429  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:12.819166  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.053s	user 0.028s	sys 0.011s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":18051,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:12.819682  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:12.830209  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.010s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3717,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:12.830716  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:12.997466  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.167s	user 0.130s	sys 0.032s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":178,"lbm_read_time_us":11460,"lbm_reads_lt_1ms":572,"lbm_write_time_us":28710,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":896,"update_count":2500}
I20260812 06:19:12.998063  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:13.051862  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.054s	user 0.032s	sys 0.013s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20461,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.052383  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:13.063668  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.011s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3854,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:13.064296  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushMRSOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:13.096341  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushMRSOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.032s	user 0.030s	sys 0.000s Metrics: {"bytes_written":1193507,"cfile_init":1,"dirs.queue_time_us":58,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":1216,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1387,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:13.097172  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling LogGCOp(6c7d5b18e45548fc94455536f68889b0): free 128867720 bytes of WAL
I20260812 06:19:13.097419  8233 log_reader.cc:385] T 6c7d5b18e45548fc94455536f68889b0: removed 13 log segments from log reader
I20260812 06:19:13.097465  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000027 (ops 130-134)
I20260812 06:19:13.097503  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000028 (ops 135-139)
I20260812 06:19:13.097537  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000029 (ops 140-144)
I20260812 06:19:13.097569  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000030 (ops 145-149)
I20260812 06:19:13.097602  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000031 (ops 150-154)
I20260812 06:19:13.097633  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000032 (ops 155-158)
I20260812 06:19:13.097663  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000033 (ops 159-163)
I20260812 06:19:13.097693  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000034 (ops 164-168)
I20260812 06:19:13.097774  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000035 (ops 169-172)
I20260812 06:19:13.097805  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000036 (ops 173-177)
I20260812 06:19:13.097829  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000037 (ops 178-182)
I20260812 06:19:13.097860  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000038 (ops 183-186)
I20260812 06:19:13.097890  8233 log.cc:1079] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: Deleting log segment in path: /tmp/dist-test-taskGCmmuI/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515543660981-7759-0/minicluster-data/ts-0-root/wals/6c7d5b18e45548fc94455536f68889b0/wal-000000039 (ops 187-191)
I20260812 06:19:13.118348  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: LogGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.021s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:19:13.118896  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0): 462 bytes on disk
I20260812 06:19:13.119429  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: UndoDeltaBlockGCOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":70,"lbm_reads_lt_1ms":4}
I20260812 06:19:13.120035  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=3.181125
I20260812 06:19:13.138504  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.018s	user 0.013s	sys 0.004s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6921,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:13.138947  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=2.188937
I20260812 06:19:13.147872  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.009s	user 0.004s	sys 0.003s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3295,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:13.148273  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0): perf score=1.000000
I20260812 06:19:13.324982  7759 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.417s	user 1.653s	sys 0.116s
I20260812 06:19:13.354465  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: MajorDeltaCompactionOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.206s	user 0.156s	sys 0.049s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":33020732,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14103,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35835,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":7680,"update_count":3500}
I20260812 06:19:13.355021  8337 maintenance_manager.cc:419] P 2c87708121e045058a68f8dbd31a77ad: Scheduling FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0): perf score=14.095187
I20260812 06:19:13.390323  7759 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.065s	user 0.000s	sys 0.002s
I20260812 06:19:13.390780  7759 tablet_server.cc:179] TabletServer@127.7.147.193:0 shutting down...
I20260812 06:19:13.432801  8233 maintenance_manager.cc:643] P 2c87708121e045058a68f8dbd31a77ad: FlushDeltaMemStoresOp(6c7d5b18e45548fc94455536f68889b0) complete. Timing: real 0.078s	user 0.024s	sys 0.006s Metrics: {"bytes_written":16409903,"delete_count":0,"lbm_write_time_us":13911,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:13.433367  7759 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:13.433568  7759 tablet_replica.cc:333] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad: stopping tablet replica
I20260812 06:19:13.433737  7759 raft_consensus.cc:2243] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:13.433916  7759 raft_consensus.cc:2272] T 6c7d5b18e45548fc94455536f68889b0 P 2c87708121e045058a68f8dbd31a77ad [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:13.436769  7759 tablet_server.cc:196] TabletServer@127.7.147.193:0 shutdown complete.
I20260812 06:19:13.439450  7759 master.cc:562] Master@127.7.147.254:36871 shutting down...
I20260812 06:19:13.442262  7759 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:13.442404  7759 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:13.442461  7759 tablet_replica.cc:333] T 00000000000000000000000000000000 P 87f6fdd7d3614066a544616e580be16f: stopping tablet replica
I20260812 06:19:13.454329  7759 master.cc:584] Master@127.7.147.254:36871 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (4838 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (9850 ms total)

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