[==========] 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:34.311769  7148 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.251.62:42023
I20260812 06:19:34.312714  7148 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:34.313272  7148 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.319312  7154 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:34.319415  7160 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:34.319506  7148 server_base.cc:1061] running on GCE node
W20260812 06:19:34.319562  7166 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:34.319972  7148 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.320073  7148 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:34.320104  7148 hybrid_clock.cc:648] HybridClock initialized: now 1786515574320102 us; error 0 us; skew 500 ppm
I20260812 06:19:34.321734  7148 webserver.cc:533] Webserver started at http://127.6.251.62:38787/ using document root <none> and password file <none>
I20260812 06:19:34.322254  7148 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.322309  7148 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.322501  7148 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.323992  7148 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/master-0-root/instance:
uuid: "6fa079fa41ed49ada77541b2056467a1"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-tc2s"
I20260812 06:19:34.327195  7148 fs_manager.cc:696] Time spent creating directory manager: real 0.003s	user 0.001s	sys 0.003s
I20260812 06:19:34.329051  7172 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:34.330026  7148 fs_manager.cc:730] Time spent opening block manager: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:34.330121  7148 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/master-0-root
uuid: "6fa079fa41ed49ada77541b2056467a1"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-tc2s"
I20260812 06:19:34.330207  7148 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-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:34.349161  7148 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.349704  7148 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:34.349839  7148 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.356667  7148 rpc_server.cc:307] RPC server started. Bound to: 127.6.251.62:42023
I20260812 06:19:34.356700  7270 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.251.62:42023 every 8 connection(s)
I20260812 06:19:34.358767  7271 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:34.364542  7271 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: Bootstrap starting.
I20260812 06:19:34.367307  7271 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.368381  7271 log.cc:826] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: Log is configured to *not* fsync() on all Append() calls
I20260812 06:19:34.370153  7271 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: No bootstrap required, opened a new log
I20260812 06:19:34.372848  7271 raft_consensus.cc:359] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER }
I20260812 06:19:34.373016  7271 raft_consensus.cc:385] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.373093  7271 raft_consensus.cc:740] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 6fa079fa41ed49ada77541b2056467a1, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.373649  7271 consensus_queue.cc:260] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [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: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER }
I20260812 06:19:34.373827  7271 raft_consensus.cc:399] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.373914  7271 raft_consensus.cc:493] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.374033  7271 raft_consensus.cc:3060] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.374840  7271 raft_consensus.cc:515] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER }
I20260812 06:19:34.375296  7271 leader_election.cc:304] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [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: 6fa079fa41ed49ada77541b2056467a1; no voters: 
I20260812 06:19:34.375633  7271 leader_election.cc:290] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.375723  7276 raft_consensus.cc:2804] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.375934  7276 raft_consensus.cc:697] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 1 LEADER]: Becoming Leader. State: Replica: 6fa079fa41ed49ada77541b2056467a1, State: Running, Role: LEADER
I20260812 06:19:34.376286  7276 consensus_queue.cc:237] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [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: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER }
I20260812 06:19:34.376610  7271 sys_catalog.cc:565] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:34.377960  7282 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "6fa079fa41ed49ada77541b2056467a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER } }
I20260812 06:19:34.378136  7282 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.378510  7293 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:34.378486  7283 sys_catalog.cc:455] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [sys.catalog]: SysCatalogTable state changed. Reason: New leader 6fa079fa41ed49ada77541b2056467a1. Latest consensus state: current_term: 1 leader_uuid: "6fa079fa41ed49ada77541b2056467a1" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "6fa079fa41ed49ada77541b2056467a1" member_type: VOTER } }
I20260812 06:19:34.378647  7283 sys_catalog.cc:458] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:34.381145  7293 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:34.381443  7148 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:34.390159  7293 catalog_manager.cc:1383] Generated new cluster ID: fa33a0a5f32a412682dd90b439178fd1
I20260812 06:19:34.390265  7293 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:34.405226  7293 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:34.406054  7293 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:34.419194  7293 catalog_manager.cc:6092] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: Generated new TSK 0
I20260812 06:19:34.419857  7293 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:34.448148  7148 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:34.450482  7322 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:34.450557  7326 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:34.450707  7323 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:34.450743  7148 server_base.cc:1061] running on GCE node
I20260812 06:19:34.450886  7148 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:34.450933  7148 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:34.450953  7148 hybrid_clock.cc:648] HybridClock initialized: now 1786515574450953 us; error 0 us; skew 500 ppm
I20260812 06:19:34.451785  7148 webserver.cc:533] Webserver started at http://127.6.251.1:34103/ using document root <none> and password file <none>
I20260812 06:19:34.451947  7148 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:34.452004  7148 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:34.452077  7148 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:34.452407  7148 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/instance:
uuid: "4b09c50f99ab4188b792b6050dfa8b43"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-tc2s"
I20260812 06:19:34.453783  7148 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:34.454697  7335 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:34.454921  7148 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.001s	sys 0.000s
I20260812 06:19:34.454985  7148 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root
uuid: "4b09c50f99ab4188b792b6050dfa8b43"
format_stamp: "Formatted at 2026-08-12 06:19:34 on dist-test-slave-tc2s"
I20260812 06:19:34.455044  7148 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-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:34.471390  7148 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:34.471798  7148 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:34.472244  7148 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:34.473084  7148 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:34.473137  7148 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.473182  7148 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:34.473212  7148 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:34.479574  7148 rpc_server.cc:307] RPC server started. Bound to: 127.6.251.1:34741
I20260812 06:19:34.479627  7441 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.251.1:34741 every 8 connection(s)
I20260812 06:19:34.488628  7443 heartbeater.cc:344] Connected to a master server at 127.6.251.62:42023
I20260812 06:19:34.488828  7443 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:34.489238  7443 heartbeater.cc:507] Master 127.6.251.62:42023 requested a full tablet report, sending...
I20260812 06:19:34.490656  7203 ts_manager.cc:194] Registered new tserver with Master: 4b09c50f99ab4188b792b6050dfa8b43 (127.6.251.1:34741)
I20260812 06:19:34.491259  7148 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.01108888s
I20260812 06:19:34.492071  7203 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:60200
I20260812 06:19:34.499641  7203 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:60210:
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:34.513029  7379 tablet_service.cc:1511] Processing CreateTablet for tablet 5fdaa00b54b04bb7b108f59c0b390bf2 (DEFAULT_TABLE table=heavy-update-compaction-test [id=679c24f894014865b6067132571f2e4f]), partition=
I20260812 06:19:34.513441  7379 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 5fdaa00b54b04bb7b108f59c0b390bf2. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:34.516094  7462 tablet_bootstrap.cc:492] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Bootstrap starting.
I20260812 06:19:34.517383  7462 tablet_bootstrap.cc:654] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:34.518674  7462 tablet_bootstrap.cc:492] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: No bootstrap required, opened a new log
I20260812 06:19:34.518788  7462 ts_tablet_manager.cc:1403] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Time spent bootstrapping tablet: real 0.003s	user 0.002s	sys 0.000s
I20260812 06:19:34.519286  7462 raft_consensus.cc:359] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b09c50f99ab4188b792b6050dfa8b43" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 34741 } }
I20260812 06:19:34.519411  7462 raft_consensus.cc:385] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:34.519462  7462 raft_consensus.cc:740] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: 4b09c50f99ab4188b792b6050dfa8b43, State: Initialized, Role: FOLLOWER
I20260812 06:19:34.519601  7462 consensus_queue.cc:260] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [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: "4b09c50f99ab4188b792b6050dfa8b43" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 34741 } }
I20260812 06:19:34.519698  7462 raft_consensus.cc:399] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:34.519742  7462 raft_consensus.cc:493] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:34.519791  7462 raft_consensus.cc:3060] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:34.520727  7462 raft_consensus.cc:515] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b09c50f99ab4188b792b6050dfa8b43" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 34741 } }
I20260812 06:19:34.520928  7462 leader_election.cc:304] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [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: 4b09c50f99ab4188b792b6050dfa8b43; no voters: 
I20260812 06:19:34.521201  7462 leader_election.cc:290] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:34.521289  7467 raft_consensus.cc:2804] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:34.521513  7467 raft_consensus.cc:697] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 1 LEADER]: Becoming Leader. State: Replica: 4b09c50f99ab4188b792b6050dfa8b43, State: Running, Role: LEADER
I20260812 06:19:34.521576  7462 ts_tablet_manager.cc:1434] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Time spent starting tablet: real 0.003s	user 0.003s	sys 0.000s
I20260812 06:19:34.521754  7443 heartbeater.cc:499] Master 127.6.251.62:42023 was elected leader, sending a full tablet report...
I20260812 06:19:34.522075  7467 consensus_queue.cc:237] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [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: "4b09c50f99ab4188b792b6050dfa8b43" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 34741 } }
I20260812 06:19:34.524513  7203 catalog_manager.cc:5719] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 reported cstate change: term changed from 0 to 1, leader changed from <none> to 4b09c50f99ab4188b792b6050dfa8b43 (127.6.251.1). New cstate: current_term: 1 leader_uuid: "4b09c50f99ab4188b792b6050dfa8b43" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "4b09c50f99ab4188b792b6050dfa8b43" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 34741 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:34.585253  7148 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.052s	user 0.011s	sys 0.012s
I20260812 06:19:34.730710  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=19.054940
I20260812 06:19:34.923331  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.192s	user 0.153s	sys 0.036s Metrics: {"bytes_written":16409902,"cfile_init":1,"compiler_manager_pool.queue_time_us":180,"delete_count":0,"dirs.queue_time_us":68,"dirs.run_cpu_time_us":201,"dirs.run_wall_time_us":922,"drs_written":1,"lbm_read_time_us":78,"lbm_reads_lt_1ms":4,"lbm_write_time_us":46734,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":104,"thread_start_us":91,"threads_started":1,"update_count":2000}
I20260812 06:19:34.924340  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): free 20743880 bytes of WAL
I20260812 06:19:34.924613  7343 log_reader.cc:385] T 5fdaa00b54b04bb7b108f59c0b390bf2: removed 2 log segments from log reader
I20260812 06:19:34.924671  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000001 (ops 1-6)
I20260812 06:19:34.924749  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000002 (ops 7-11)
I20260812 06:19:34.928459  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:34.928735  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): 16411392 bytes on disk
I20260812 06:19:34.929224  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4}
I20260812 06:19:34.929589  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:34.943704  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5541,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:34.944235  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.100037  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.156s	user 0.113s	sys 0.042s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":7,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":315,"lbm_read_time_us":12697,"lbm_reads_lt_1ms":560,"lbm_write_time_us":25361,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2944,"thread_start_us":275,"threads_started":5,"update_count":2500}
I20260812 06:19:35.100630  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:35.134912  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.034s	user 0.020s	sys 0.012s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13907,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.135354  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:35.151816  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.016s	user 0.002s	sys 0.012s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4944,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.152343  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.272967  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.120s	user 0.088s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672276,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":148,"lbm_read_time_us":9070,"lbm_reads_lt_1ms":464,"lbm_write_time_us":20890,"lbm_writes_lt_1ms":443,"mutex_wait_us":81,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1920,"update_count":2000}
I20260812 06:19:35.273460  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:35.315409  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.042s	user 0.016s	sys 0.015s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13799,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.315960  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:35.330682  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5296,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.331183  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.451799  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.120s	user 0.098s	sys 0.023s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":133,"lbm_read_time_us":8223,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23919,"lbm_writes_lt_1ms":443,"mutex_wait_us":28,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2176,"update_count":2000}
I20260812 06:19:35.452291  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:35.493592  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.041s	user 0.015s	sys 0.017s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15152,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.494123  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:35.503639  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.009s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3557,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.504066  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.624486  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.120s	user 0.104s	sys 0.016s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":851,"lbm_read_time_us":9104,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22374,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7296,"update_count":2000}
I20260812 06:19:35.624936  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:35.671375  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.046s	user 0.018s	sys 0.019s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13417,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.671895  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:35.686578  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5638,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.687031  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.824370  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.137s	user 0.104s	sys 0.032s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":864,"lbm_read_time_us":10915,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21037,"lbm_writes_lt_1ms":443,"mutex_wait_us":282,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:35.824975  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:35.871668  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.047s	user 0.023s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15686,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:35.872135  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:35.882682  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3945,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:35.883188  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:35.998857  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.115s	user 0.091s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672277,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1028,"lbm_read_time_us":9382,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20418,"lbm_writes_lt_1ms":443,"mutex_wait_us":329,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":3840,"update_count":2000}
I20260812 06:19:35.999372  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:36.033036  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.033s	user 0.008s	sys 0.019s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":12752,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.033553  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.048406  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5510,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.048884  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:36.077524  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.028s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193503,"cfile_init":1,"dirs.queue_time_us":74,"dirs.run_cpu_time_us":187,"dirs.run_wall_time_us":1278,"drs_written":1,"lbm_read_time_us":47,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1368,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:36.078435  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): free 112692363 bytes of WAL
I20260812 06:19:36.078637  7343 log_reader.cc:385] T 5fdaa00b54b04bb7b108f59c0b390bf2: removed 11 log segments from log reader
I20260812 06:19:36.078684  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000003 (ops 12-16)
I20260812 06:19:36.078717  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000004 (ops 17-21)
I20260812 06:19:36.078752  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000005 (ops 22-26)
I20260812 06:19:36.078781  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000006 (ops 27-31)
I20260812 06:19:36.078809  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000007 (ops 32-36)
I20260812 06:19:36.078836  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000008 (ops 37-41)
I20260812 06:19:36.078866  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000009 (ops 42-46)
I20260812 06:19:36.078899  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000010 (ops 47-51)
I20260812 06:19:36.078927  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000011 (ops 52-56)
I20260812 06:19:36.078955  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000012 (ops 57-61)
I20260812 06:19:36.078982  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000013 (ops 62-66)
I20260812 06:19:36.102525  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:36.102993  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): 462 bytes on disk
I20260812 06:19:36.103490  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:36.103947  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=3.181125
I20260812 06:19:36.118211  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.014s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":4299,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:36.118593  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.127544  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3337,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.127902  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:36.294186  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.166s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28877327,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":554,"lbm_read_time_us":11199,"lbm_reads_lt_1ms":674,"lbm_write_time_us":33249,"lbm_writes_lt_1ms":643,"mutex_wait_us":67,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":9856,"thread_start_us":111,"threads_started":1,"update_count":3000}
I20260812 06:19:36.295050  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:36.347013  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.052s	user 0.019s	sys 0.032s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":21577,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.347491  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.362288  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.014s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5695,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.362875  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:36.512367  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.149s	user 0.115s	sys 0.028s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1041,"lbm_read_time_us":9131,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28424,"lbm_writes_lt_1ms":543,"mutex_wait_us":342,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":16128,"update_count":2500}
I20260812 06:19:36.512861  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:36.554924  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.042s	user 0.029s	sys 0.011s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":18602,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.555401  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:36.686074  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.130s	user 0.085s	sys 0.044s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672158,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":1713,"lbm_read_time_us":9400,"lbm_reads_lt_1ms":467,"lbm_write_time_us":22693,"lbm_writes_lt_1ms":443,"mutex_wait_us":536,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":12672,"update_count":2000}
I20260812 06:19:36.686573  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=10.126437
I20260812 06:19:36.717777  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.031s	user 0.016s	sys 0.012s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":13563,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:36.718351  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.734010  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.010s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5619,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.734506  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:36.866950  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.132s	user 0.096s	sys 0.029s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672278,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":125,"lbm_read_time_us":7266,"lbm_reads_lt_1ms":468,"lbm_write_time_us":25204,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:36.867540  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=11.118625
I20260812 06:19:36.907920  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.040s	user 0.012s	sys 0.026s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":17513,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":312,"reinsert_count":0,"update_count":1550}
I20260812 06:19:36.908370  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.927748  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.019s	user 0.004s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5674,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:36.928155  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:36.936751  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.008s	user 0.003s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3263,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:36.937137  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:37.082149  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.145s	user 0.107s	sys 0.037s Metrics: {"cfile_cache_miss":533,"cfile_cache_miss_bytes":24774799,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":430,"lbm_read_time_us":10455,"lbm_reads_lt_1ms":573,"lbm_write_time_us":27937,"lbm_writes_lt_1ms":543,"mutex_wait_us":20,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2500}
I20260812 06:19:37.085330  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=11.118625
I20260812 06:19:37.115595  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.030s	user 0.017s	sys 0.012s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12698,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:37.116084  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:37.134665  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.018s	user 0.007s	sys 0.008s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":6073,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.135179  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:37.268121  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.133s	user 0.103s	sys 0.024s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20672268,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":630,"lbm_read_time_us":9415,"lbm_reads_lt_1ms":468,"lbm_write_time_us":24174,"lbm_writes_lt_1ms":443,"mutex_wait_us":279,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:37.268667  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=11.118625
I20260812 06:19:37.312006  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.043s	user 0.024s	sys 0.016s Metrics: {"bytes_written":12717736,"delete_count":0,"lbm_write_time_us":15026,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:37.312549  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:37.329006  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.016s	user 0.007s	sys 0.004s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4863,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:37.329442  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:37.365839  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.036s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1193509,"cfile_init":1,"dirs.queue_time_us":38,"dirs.run_cpu_time_us":182,"dirs.run_wall_time_us":1236,"drs_written":1,"lbm_read_time_us":42,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1502,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":29}
I20260812 06:19:37.366611  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): free 124257190 bytes of WAL
I20260812 06:19:37.366848  7343 log_reader.cc:385] T 5fdaa00b54b04bb7b108f59c0b390bf2: removed 12 log segments from log reader
I20260812 06:19:37.366895  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000014 (ops 67-71)
I20260812 06:19:37.366936  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000015 (ops 72-76)
I20260812 06:19:37.366971  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000016 (ops 77-81)
I20260812 06:19:37.367003  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000017 (ops 82-86)
I20260812 06:19:37.367035  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000018 (ops 87-91)
I20260812 06:19:37.367066  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000019 (ops 92-96)
I20260812 06:19:37.367098  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000020 (ops 97-101)
I20260812 06:19:37.367129  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000021 (ops 102-106)
I20260812 06:19:37.367161  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000022 (ops 107-110)
I20260812 06:19:37.367193  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000023 (ops 111-115)
I20260812 06:19:37.367224  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000024 (ops 116-120)
I20260812 06:19:37.367254  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000025 (ops 121-125)
I20260812 06:19:37.387342  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.021s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:37.387717  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): 462 bytes on disk
I20260812 06:19:37.388166  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":63,"lbm_reads_lt_1ms":4}
I20260812 06:19:37.388653  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=6.157687
I20260812 06:19:37.418413  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.030s	user 0.020s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":11492,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:37.418884  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:37.603444  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.184s	user 0.097s	sys 0.087s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877213,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":336,"lbm_read_time_us":12648,"lbm_reads_lt_1ms":669,"lbm_write_time_us":32359,"lbm_writes_lt_1ms":643,"mutex_wait_us":19,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":16640,"thread_start_us":75,"threads_started":1,"update_count":3000}
I20260812 06:19:37.605518  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:37.657698  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.052s	user 0.021s	sys 0.027s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":22767,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:37.658135  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:37.677928  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.020s	user 0.010s	sys 0.001s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4882,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.678360  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:37.687692  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.009s	user 0.002s	sys 0.005s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3536,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.688163  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:37.862408  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.174s	user 0.130s	sys 0.043s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28877218,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":393,"lbm_read_time_us":13319,"lbm_reads_lt_1ms":673,"lbm_write_time_us":28079,"lbm_writes_lt_1ms":643,"mutex_wait_us":280,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":14848,"update_count":3000}
I20260812 06:19:37.863006  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:37.911854  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.049s	user 0.032s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":21456,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:37.912434  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:37.928017  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.015s	user 0.010s	sys 0.003s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":6074,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:37.928522  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:38.086355  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.158s	user 0.097s	sys 0.060s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774688,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":837,"lbm_read_time_us":10251,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26568,"lbm_writes_lt_1ms":543,"mutex_wait_us":240,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":6400,"update_count":2500}
I20260812 06:19:38.086889  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:38.133543  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.046s	user 0.022s	sys 0.020s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":19590,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.134101  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:38.148627  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.014s	user 0.012s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5620,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.149062  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:38.315915  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.167s	user 0.125s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774687,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":215,"lbm_read_time_us":12449,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27680,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":768,"update_count":2500}
I20260812 06:19:38.316444  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:38.367877  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.050s	user 0.016s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17465,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.368402  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:38.378815  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.010s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3973,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.379294  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:38.563024  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.184s	user 0.090s	sys 0.083s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774689,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":231,"lbm_read_time_us":12440,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29655,"lbm_writes_lt_1ms":543,"mutex_wait_us":22,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":46208,"update_count":2500}
I20260812 06:19:38.563544  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:38.611891  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.048s	user 0.026s	sys 0.020s Metrics: {"bytes_written":16409904,"delete_count":0,"lbm_write_time_us":19167,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.612386  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:38.630553  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.018s	user 0.006s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3716,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.631147  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:38.810027  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.179s	user 0.123s	sys 0.048s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24774691,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":991,"lbm_read_time_us":11993,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26075,"lbm_writes_lt_1ms":543,"mutex_wait_us":294,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":7424,"update_count":2500}
I20260812 06:19:38.810528  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:38.854911  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.044s	user 0.021s	sys 0.016s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":17038,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:38.855414  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:38.866204  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.011s	user 0.006s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4022,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:38.866745  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:38.902479  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushMRSOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.035s	user 0.026s	sys 0.004s Metrics: {"bytes_written":1316417,"cfile_init":1,"dirs.queue_time_us":63,"dirs.run_cpu_time_us":223,"dirs.run_wall_time_us":1323,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1550,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":32}
I20260812 06:19:38.903118  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): free 129320818 bytes of WAL
I20260812 06:19:38.903343  7343 log_reader.cc:385] T 5fdaa00b54b04bb7b108f59c0b390bf2: removed 13 log segments from log reader
I20260812 06:19:38.903390  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000026 (ops 126-130)
I20260812 06:19:38.903416  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000027 (ops 131-135)
I20260812 06:19:38.903445  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000028 (ops 136-140)
I20260812 06:19:38.903478  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000029 (ops 141-145)
I20260812 06:19:38.903510  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000030 (ops 146-150)
I20260812 06:19:38.903541  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000031 (ops 151-154)
I20260812 06:19:38.903573  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000032 (ops 155-159)
I20260812 06:19:38.903604  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000033 (ops 160-164)
I20260812 06:19:38.903635  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000034 (ops 165-168)
I20260812 06:19:38.903666  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000035 (ops 169-173)
I20260812 06:19:38.903697  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000036 (ops 174-178)
I20260812 06:19:38.903726  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000037 (ops 179-183)
I20260812 06:19:38.903759  7343 log.cc:1079] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_0.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/5fdaa00b54b04bb7b108f59c0b390bf2/wal-000000038 (ops 184-188)
I20260812 06:19:38.926803  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: LogGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.024s	user 0.000s	sys 0.023s Metrics: {}
I20260812 06:19:38.927227  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2): 493 bytes on disk
I20260812 06:19:38.927738  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: UndoDeltaBlockGCOp(5fdaa00b54b04bb7b108f59c0b390bf2) 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:38.928367  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=3.181125
I20260812 06:19:38.954578  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.026s	user 0.012s	sys 0.003s Metrics: {"bytes_written":4512900,"delete_count":0,"lbm_write_time_us":6304,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:38.955005  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=2.188937
I20260812 06:19:38.963846  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.009s	user 0.007s	sys 0.000s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3278,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:38.964248  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:39.144655  7148 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.559s	user 1.655s	sys 0.131s
I20260812 06:19:39.176712  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.212s	user 0.138s	sys 0.072s Metrics: {"cfile_cache_miss":734,"cfile_cache_miss_bytes":32979737,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"lbm_read_time_us":14486,"lbm_reads_lt_1ms":770,"lbm_write_time_us":35891,"lbm_writes_lt_1ms":743,"peak_mem_usage":87969044,"reinsert_count":0,"spinlock_wait_cycles":1536,"update_count":3500}
I20260812 06:19:39.177177  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=14.095187
I20260812 06:19:39.208478  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: FlushDeltaMemStoresOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.031s	user 0.019s	sys 0.011s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":14803,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:39.209054  7446 maintenance_manager.cc:419] P 4b09c50f99ab4188b792b6050dfa8b43: Scheduling MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2): perf score=1.000000
I20260812 06:19:39.248389  7148 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.103s	user 0.001s	sys 0.000s
I20260812 06:19:39.248986  7148 tablet_server.cc:179] TabletServer@127.6.251.1:0 shutting down...
I20260812 06:19:39.332962  7343 maintenance_manager.cc:643] P 4b09c50f99ab4188b792b6050dfa8b43: MajorDeltaCompactionOp(5fdaa00b54b04bb7b108f59c0b390bf2) complete. Timing: real 0.124s	user 0.087s	sys 0.036s Metrics: {"cfile_cache_miss":431,"cfile_cache_miss_bytes":20672157,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":1,"delta_iterators_relevant":1,"dirs.queue_time_us":330,"lbm_read_time_us":11250,"lbm_reads_1-10_ms":1,"lbm_reads_lt_1ms":466,"lbm_write_time_us":26233,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":441,"mutex_wait_us":48,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":516992,"update_count":2000}
I20260812 06:19:39.333943  7148 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:39.334421  7148 tablet_replica.cc:333] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43: stopping tablet replica
I20260812 06:19:39.334689  7148 raft_consensus.cc:2243] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:39.334941  7148 raft_consensus.cc:2272] T 5fdaa00b54b04bb7b108f59c0b390bf2 P 4b09c50f99ab4188b792b6050dfa8b43 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:39.351825  7148 tablet_server.cc:196] TabletServer@127.6.251.1:0 shutdown complete.
I20260812 06:19:39.371446  7148 master.cc:562] Master@127.6.251.62:42023 shutting down...
I20260812 06:19:39.374953  7148 raft_consensus.cc:2243] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:39.375123  7148 raft_consensus.cc:2272] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:39.375196  7148 tablet_replica.cc:333] T 00000000000000000000000000000000 P 6fa079fa41ed49ada77541b2056467a1: stopping tablet replica
I20260812 06:19:39.387233  7148 master.cc:584] Master@127.6.251.62:42023 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/0 (5154 ms)
[ RUN      ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1
I20260812 06:19:39.466113  7148 internal_mini_cluster.cc:156] Creating distributed mini masters. Addrs: 127.6.251.62:44189
I20260812 06:19:39.466513  7148 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.468374  7504 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:39.468463  7509 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:39.468540  7511 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:39.468636  7148 server_base.cc:1061] running on GCE node
I20260812 06:19:39.468770  7148 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.468808  7148 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:39.468833  7148 hybrid_clock.cc:648] HybridClock initialized: now 1786515579468833 us; error 0 us; skew 500 ppm
I20260812 06:19:39.469630  7148 webserver.cc:533] Webserver started at http://127.6.251.62:33719/ using document root <none> and password file <none>
I20260812 06:19:39.469790  7148 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.469843  7148 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.469946  7148 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.470317  7148 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/master-0-root/instance:
uuid: "e1f6d6df71b241dc8413a7c99eac7bd3"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-tc2s"
I20260812 06:19:39.471724  7148 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.002s
I20260812 06:19:39.472587  7525 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:39.472815  7148 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:39.472884  7148 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/master-0-root
uuid: "e1f6d6df71b241dc8413a7c99eac7bd3"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-tc2s"
I20260812 06:19:39.472952  7148 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/master-0-root
metadata directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/master-0-root
1 data directories: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-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:39.487528  7148 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.487860  7148 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.491811  7148 rpc_server.cc:307] RPC server started. Bound to: 127.6.251.62:44189
I20260812 06:19:39.504925  7618 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.251.62:44189 every 8 connection(s)
I20260812 06:19:39.505355  7619 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:39.507112  7619 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3: Bootstrap starting.
I20260812 06:19:39.507872  7619 tablet_bootstrap.cc:654] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.509413  7619 tablet_bootstrap.cc:492] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3: No bootstrap required, opened a new log
I20260812 06:19:39.509807  7619 raft_consensus.cc:359] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER }
I20260812 06:19:39.509918  7619 raft_consensus.cc:385] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.509970  7619 raft_consensus.cc:740] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: e1f6d6df71b241dc8413a7c99eac7bd3, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.510123  7619 consensus_queue.cc:260] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [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: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER }
I20260812 06:19:39.510217  7619 raft_consensus.cc:399] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.510258  7619 raft_consensus.cc:493] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.510309  7619 raft_consensus.cc:3060] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.510949  7619 raft_consensus.cc:515] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER }
I20260812 06:19:39.511070  7619 leader_election.cc:304] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [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: e1f6d6df71b241dc8413a7c99eac7bd3; no voters: 
I20260812 06:19:39.511245  7619 leader_election.cc:290] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.511353  7624 raft_consensus.cc:2804] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.511569  7624 raft_consensus.cc:697] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 1 LEADER]: Becoming Leader. State: Replica: e1f6d6df71b241dc8413a7c99eac7bd3, State: Running, Role: LEADER
I20260812 06:19:39.511680  7619 sys_catalog.cc:565] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [sys.catalog]: configured and running, proceeding with master startup.
I20260812 06:19:39.511703  7624 consensus_queue.cc:237] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [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: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER }
I20260812 06:19:39.512127  7627 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [sys.catalog]: SysCatalogTable state changed. Reason: New leader e1f6d6df71b241dc8413a7c99eac7bd3. Latest consensus state: current_term: 1 leader_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER } }
I20260812 06:19:39.512215  7627 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.512110  7625 sys_catalog.cc:455] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [sys.catalog]: SysCatalogTable state changed. Reason: RaftConsensus started. Latest consensus state: current_term: 1 leader_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "e1f6d6df71b241dc8413a7c99eac7bd3" member_type: VOTER } }
I20260812 06:19:39.512266  7625 sys_catalog.cc:458] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [sys.catalog]: This master's current role is: LEADER
I20260812 06:19:39.512478  7632 catalog_manager.cc:1511] Loading table and tablet metadata into memory...
I20260812 06:19:39.513338  7632 catalog_manager.cc:1520] Initializing Kudu cluster ID...
I20260812 06:19:39.513502  7148 internal_mini_cluster.cc:184] Waiting to initialize catalog manager on master 0
I20260812 06:19:39.515043  7632 catalog_manager.cc:1383] Generated new cluster ID: 719be0eec0914f2b8ee8e3245ef3d775
I20260812 06:19:39.515097  7632 catalog_manager.cc:1531] Initializing Kudu internal certificate authority...
I20260812 06:19:39.529668  7632 catalog_manager.cc:1406] Generated new certificate authority record
I20260812 06:19:39.530215  7632 catalog_manager.cc:1540] Loading token signing keys...
I20260812 06:19:39.537590  7632 catalog_manager.cc:6092] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3: Generated new TSK 0
I20260812 06:19:39.537732  7632 catalog_manager.cc:1550] Initializing in-progress tserver states...
I20260812 06:19:39.545708  7148 file_cache.cc:504] Constructed file cache file cache with capacity 419430
W20260812 06:19:39.547605  7652 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:39.547619  7653 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:39.547816  7148 server_base.cc:1061] running on GCE node
W20260812 06:19:39.547820  7655 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:39.548151  7148 hybrid_clock.cc:584] initializing the hybrid clock with 'system_unsync' time source
W20260812 06:19:39.548207  7148 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:39.548224  7148 hybrid_clock.cc:648] HybridClock initialized: now 1786515579548225 us; error 0 us; skew 500 ppm
I20260812 06:19:39.549117  7148 webserver.cc:533] Webserver started at http://127.6.251.1:33351/ using document root <none> and password file <none>
I20260812 06:19:39.549276  7148 fs_manager.cc:362] Metadata directory not provided
I20260812 06:19:39.549336  7148 fs_manager.cc:368] Using write-ahead log directory (fs_wal_dir) as metadata directory
I20260812 06:19:39.549412  7148 server_base.cc:909] This appears to be a new deployment of Kudu; creating new FS layout
I20260812 06:19:39.549785  7148 fs_manager.cc:1068] Generated new instance metadata in path /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/instance:
uuid: "eeb4444707034bf6be626fd9e26e502f"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-tc2s"
I20260812 06:19:39.551246  7148 fs_manager.cc:696] Time spent creating directory manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:39.552170  7660 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:39.552392  7148 fs_manager.cc:730] Time spent opening block manager: real 0.001s	user 0.000s	sys 0.001s
I20260812 06:19:39.552462  7148 fs_manager.cc:647] Opened local filesystem: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root
uuid: "eeb4444707034bf6be626fd9e26e502f"
format_stamp: "Formatted at 2026-08-12 06:19:39 on dist-test-slave-tc2s"
I20260812 06:19:39.552523  7148 fs_report.cc:389] FS layout report
--------------------
wal directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root
metadata directory: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root
1 data directories: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-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:39.572047  7148 rpc_server.cc:225] running with OpenSSL 1.1.1  11 Sep 2018
I20260812 06:19:39.572383  7148 kserver.cc:163] Server-wide thread pool size limit: 3276
I20260812 06:19:39.572657  7148 txn_system_client.cc:432] TxnSystemClient initialization is disabled...
I20260812 06:19:39.573091  7148 ts_tablet_manager.cc:585] Loaded tablet metadata (0 total tablets, 0 live tablets)
I20260812 06:19:39.573128  7148 ts_tablet_manager.cc:531] Time spent load tablet metadata: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.573161  7148 ts_tablet_manager.cc:616] Registered 0 tablets
I20260812 06:19:39.573189  7148 ts_tablet_manager.cc:595] Time spent register tablets: real 0.000s	user 0.000s	sys 0.000s
I20260812 06:19:39.577307  7148 rpc_server.cc:307] RPC server started. Bound to: 127.6.251.1:33835
I20260812 06:19:39.577358  7767 acceptor_pool.cc:272] collecting diagnostics on the listening RPC socket 127.6.251.1:33835 every 8 connection(s)
I20260812 06:19:39.585811  7771 heartbeater.cc:344] Connected to a master server at 127.6.251.62:44189
I20260812 06:19:39.585916  7771 heartbeater.cc:461] Registering TS with master...
I20260812 06:19:39.586122  7771 heartbeater.cc:507] Master 127.6.251.62:44189 requested a full tablet report, sending...
I20260812 06:19:39.586726  7556 ts_manager.cc:194] Registered new tserver with Master: eeb4444707034bf6be626fd9e26e502f (127.6.251.1:33835)
I20260812 06:19:39.587401  7556 master_service.cc:502] Signed X509 certificate for tserver {username='slave'} at 127.0.0.1:44926
I20260812 06:19:39.587656  7148 internal_mini_cluster.cc:371] 1 TS(s) registered with all masters after 0.009878742s
I20260812 06:19:39.593592  7556 catalog_manager.cc:2283] Servicing CreateTable request from {username='slave'} at 127.0.0.1:44932:
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:39.601651  7711 tablet_service.cc:1511] Processing CreateTablet for tablet 84297449a5724d738740e0bbf2415db4 (DEFAULT_TABLE table=heavy-update-compaction-test [id=8cce5f7b3cfc4d688ba0d0c43cf272c7]), partition=
I20260812 06:19:39.601886  7711 data_dirs.cc:400] Could only allocate 1 dirs of requested 3 for tablet 84297449a5724d738740e0bbf2415db4. 1 dirs total, 0 dirs full, 0 dirs failed
I20260812 06:19:39.603662  7796 tablet_bootstrap.cc:492] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Bootstrap starting.
I20260812 06:19:39.604519  7796 tablet_bootstrap.cc:654] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Neither blocks nor log segments found. Creating new log.
I20260812 06:19:39.605484  7796 tablet_bootstrap.cc:492] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: No bootstrap required, opened a new log
I20260812 06:19:39.605567  7796 ts_tablet_manager.cc:1403] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Time spent bootstrapping tablet: real 0.002s	user 0.001s	sys 0.000s
I20260812 06:19:39.605985  7796 raft_consensus.cc:359] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Replica starting. Triggering 0 pending ops. Active config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb4444707034bf6be626fd9e26e502f" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 33835 } }
I20260812 06:19:39.606069  7796 raft_consensus.cc:385] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Consensus starting up: Expiring failure detector timer to make a prompt election more likely
I20260812 06:19:39.606101  7796 raft_consensus.cc:740] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Becoming Follower/Learner. State: Replica: eeb4444707034bf6be626fd9e26e502f, State: Initialized, Role: FOLLOWER
I20260812 06:19:39.606230  7796 consensus_queue.cc:260] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [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: "eeb4444707034bf6be626fd9e26e502f" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 33835 } }
I20260812 06:19:39.606313  7796 raft_consensus.cc:399] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Only one voter in the Raft config. Triggering election immediately
I20260812 06:19:39.606354  7796 raft_consensus.cc:493] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Starting leader election (initial election of a single-replica configuration)
I20260812 06:19:39.606403  7796 raft_consensus.cc:3060] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 0 FOLLOWER]: Advancing to term 1
I20260812 06:19:39.607136  7796 raft_consensus.cc:515] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 1 FOLLOWER]: Starting leader election with config: opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb4444707034bf6be626fd9e26e502f" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 33835 } }
I20260812 06:19:39.607263  7796 leader_election.cc:304] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [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: eeb4444707034bf6be626fd9e26e502f; no voters: 
I20260812 06:19:39.607448  7796 leader_election.cc:290] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [CANDIDATE]: Term 1 election: Requested vote from peers 
I20260812 06:19:39.607686  7801 raft_consensus.cc:2804] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 1 FOLLOWER]: Leader election won for term 1
I20260812 06:19:39.607700  7796 ts_tablet_manager.cc:1434] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Time spent starting tablet: real 0.002s	user 0.002s	sys 0.000s
I20260812 06:19:39.607856  7771 heartbeater.cc:499] Master 127.6.251.62:44189 was elected leader, sending a full tablet report...
I20260812 06:19:39.608095  7801 raft_consensus.cc:697] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 1 LEADER]: Becoming Leader. State: Replica: eeb4444707034bf6be626fd9e26e502f, State: Running, Role: LEADER
I20260812 06:19:39.608213  7801 consensus_queue.cc:237] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [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: "eeb4444707034bf6be626fd9e26e502f" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 33835 } }
I20260812 06:19:39.609452  7556 catalog_manager.cc:5719] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f reported cstate change: term changed from 0 to 1, leader changed from <none> to eeb4444707034bf6be626fd9e26e502f (127.6.251.1). New cstate: current_term: 1 leader_uuid: "eeb4444707034bf6be626fd9e26e502f" committed_config { opid_index: -1 OBSOLETE_local: true peers { permanent_uuid: "eeb4444707034bf6be626fd9e26e502f" member_type: VOTER last_known_addr { host: "127.6.251.1" port: 33835 } health_report { overall_health: HEALTHY } } }
I20260812 06:19:39.668228  7148 heavy-update-compaction-itest.cc:215] Time spent inserting: real 0.055s	user 0.014s	sys 0.008s
I20260812 06:19:39.828289  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushMRSOp(84297449a5724d738740e0bbf2415db4): perf score=23.023690
I20260812 06:19:39.992144  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushMRSOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.164s	user 0.117s	sys 0.044s Metrics: {"bytes_written":12307491,"cfile_init":1,"delete_count":0,"dirs.queue_time_us":56,"dirs.run_cpu_time_us":160,"dirs.run_wall_time_us":855,"drs_written":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4,"lbm_write_time_us":42765,"lbm_writes_lt_1ms":857,"peak_mem_usage":0,"reinsert_count":0,"rows_written":105,"update_count":1500}
I20260812 06:19:39.992743  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling LogGCOp(84297449a5724d738740e0bbf2415db4): free 20743880 bytes of WAL
I20260812 06:19:39.992971  7670 log_reader.cc:385] T 84297449a5724d738740e0bbf2415db4: removed 2 log segments from log reader
I20260812 06:19:39.993021  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000001 (ops 1-6)
I20260812 06:19:39.993059  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000002 (ops 7-11)
I20260812 06:19:39.996692  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: LogGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.004s	user 0.000s	sys 0.001s Metrics: {}
I20260812 06:19:39.997067  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4): 20513814 bytes on disk
I20260812 06:19:39.997514  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":54,"lbm_reads_lt_1ms":4}
I20260812 06:19:39.997987  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.008607  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3805,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.009013  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:40.159248  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.150s	user 0.090s	sys 0.060s Metrics: {"cfile_cache_miss":432,"cfile_cache_miss_bytes":20713273,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":445,"lbm_read_time_us":10424,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22322,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"thread_start_us":296,"threads_started":5,"update_count":2000}
I20260812 06:19:40.159777  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:40.195526  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.036s	user 0.015s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13329,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.196035  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.211760  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.016s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5977,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.212298  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:40.331825  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.119s	user 0.091s	sys 0.027s 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":1184,"lbm_read_time_us":7663,"lbm_reads_lt_1ms":464,"lbm_write_time_us":22179,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2000}
I20260812 06:19:40.332420  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:40.367671  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.035s	user 0.017s	sys 0.015s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":15144,"lbm_writes_1-10_ms":1,"lbm_writes_lt_1ms":302,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.368718  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.380420  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.012s	user 0.003s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4491,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.380878  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:40.500133  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.119s	user 0.082s	sys 0.036s 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":1187,"lbm_read_time_us":8538,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20515,"lbm_writes_lt_1ms":443,"mutex_wait_us":376,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":19968,"update_count":2000}
I20260812 06:19:40.500792  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:40.540207  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.039s	user 0.018s	sys 0.018s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":12327,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.540791  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.555488  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.015s	user 0.005s	sys 0.008s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":5646,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.555932  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:40.699612  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.144s	user 0.083s	sys 0.060s 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":285,"lbm_read_time_us":11286,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21905,"lbm_writes_lt_1ms":443,"mutex_wait_us":94,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1664,"update_count":2000}
I20260812 06:19:40.700147  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:40.736850  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.037s	user 0.020s	sys 0.007s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13104,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.737304  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.747238  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3843,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.747754  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:40.863634  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.116s	user 0.083s	sys 0.031s 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":178,"lbm_read_time_us":8540,"lbm_reads_lt_1ms":472,"lbm_write_time_us":20968,"lbm_writes_lt_1ms":443,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1792,"update_count":2000}
I20260812 06:19:40.864253  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:40.907004  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.043s	user 0.020s	sys 0.020s Metrics: {"bytes_written":12307491,"delete_count":0,"lbm_write_time_us":16173,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:40.907557  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:40.918828  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.011s	user 0.010s	sys 0.000s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":4152,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:40.919348  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:41.037220  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.118s	user 0.105s	sys 0.012s 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":852,"lbm_read_time_us":9437,"lbm_reads_lt_1ms":472,"lbm_write_time_us":21621,"lbm_writes_lt_1ms":443,"mutex_wait_us":314,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:41.037767  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:41.081547  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.044s	user 0.022s	sys 0.016s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13785,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:41.082108  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:41.096694  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.014s	user 0.008s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5700,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.097138  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushMRSOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:41.125867  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushMRSOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.029s	user 0.027s	sys 0.000s Metrics: {"bytes_written":1152508,"cfile_init":1,"dirs.queue_time_us":67,"dirs.run_cpu_time_us":255,"dirs.run_wall_time_us":1308,"drs_written":1,"lbm_read_time_us":36,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1503,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:41.126689  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:41.278477  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.152s	user 0.111s	sys 0.034s 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":453,"lbm_read_time_us":10897,"lbm_reads_lt_1ms":464,"lbm_write_time_us":21786,"lbm_writes_lt_1ms":443,"mutex_wait_us":266,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7808,"update_count":2000}
I20260812 06:19:41.278980  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling LogGCOp(84297449a5724d738740e0bbf2415db4): free 112692363 bytes of WAL
I20260812 06:19:41.279331  7670 log_reader.cc:385] T 84297449a5724d738740e0bbf2415db4: removed 11 log segments from log reader
I20260812 06:19:41.279381  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000003 (ops 12-16)
I20260812 06:19:41.279420  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000004 (ops 17-21)
I20260812 06:19:41.279492  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000005 (ops 22-26)
I20260812 06:19:41.279531  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000006 (ops 27-31)
I20260812 06:19:41.279579  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000007 (ops 32-36)
I20260812 06:19:41.279615  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000008 (ops 37-41)
I20260812 06:19:41.279663  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000009 (ops 42-46)
I20260812 06:19:41.279702  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000010 (ops 47-51)
I20260812 06:19:41.279749  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000011 (ops 52-56)
I20260812 06:19:41.279784  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000012 (ops 57-61)
I20260812 06:19:41.279829  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000013 (ops 62-66)
I20260812 06:19:41.300848  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: LogGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.022s	user 0.000s	sys 0.019s Metrics: {}
I20260812 06:19:41.301324  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4): 446 bytes on disk
I20260812 06:19:41.301877  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":74,"lbm_reads_lt_1ms":4}
I20260812 06:19:41.302412  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=15.087375
I20260812 06:19:41.349663  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.047s	user 0.032s	sys 0.011s Metrics: {"bytes_written":16820142,"delete_count":0,"lbm_write_time_us":20297,"lbm_writes_lt_1ms":413,"reinsert_count":0,"update_count":2050}
I20260812 06:19:41.350114  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:41.381265  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.031s	user 0.014s	sys 0.007s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5759,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.381790  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:41.394883  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.013s	user 0.007s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4964,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:41.395416  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:41.587854  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.192s	user 0.120s	sys 0.072s Metrics: {"cfile_cache_miss":633,"cfile_cache_miss_bytes":28918201,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":175,"lbm_read_time_us":16014,"lbm_reads_lt_1ms":673,"lbm_write_time_us":30457,"lbm_writes_lt_1ms":643,"mutex_wait_us":27,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":90880,"update_count":3000}
I20260812 06:19:41.588313  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:41.644904  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.056s	user 0.022s	sys 0.031s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":20545,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.645351  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:41.655473  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.008s	sys 0.000s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3873,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.655900  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:41.832865  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.177s	user 0.106s	sys 0.060s 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":295,"lbm_read_time_us":11455,"lbm_reads_lt_1ms":572,"lbm_write_time_us":26635,"lbm_writes_lt_1ms":543,"mutex_wait_us":52,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":25088,"update_count":2500}
I20260812 06:19:41.833338  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:41.876461  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.043s	user 0.031s	sys 0.007s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":17564,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:41.876935  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:41.895716  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.019s	user 0.002s	sys 0.015s Metrics: {"bytes_written":4102658,"delete_count":0,"lbm_write_time_us":3906,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:41.896142  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:42.079100  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.183s	user 0.103s	sys 0.070s 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":224,"lbm_read_time_us":11719,"lbm_reads_lt_1ms":572,"lbm_write_time_us":29322,"lbm_writes_lt_1ms":543,"mutex_wait_us":32,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":20608,"update_count":2500}
I20260812 06:19:42.079610  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:42.127879  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.048s	user 0.025s	sys 0.009s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":15779,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.128352  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:42.138128  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.005s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3751,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.138692  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:42.308876  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.170s	user 0.114s	sys 0.050s 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":624,"lbm_read_time_us":11448,"lbm_reads_lt_1ms":572,"lbm_write_time_us":27968,"lbm_writes_lt_1ms":543,"mutex_wait_us":268,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":8576,"update_count":2500}
I20260812 06:19:42.309415  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:42.357100  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.048s	user 0.027s	sys 0.015s Metrics: {"bytes_written":16409900,"delete_count":0,"lbm_write_time_us":20448,"lbm_writes_lt_1ms":403,"reinsert_count":0,"update_count":2000}
I20260812 06:19:42.357625  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:42.372236  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.014s	user 0.002s	sys 0.011s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5964,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.372855  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:42.508270  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.135s	user 0.077s	sys 0.056s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815682,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":208,"lbm_read_time_us":10304,"lbm_reads_lt_1ms":572,"lbm_write_time_us":25755,"lbm_writes_lt_1ms":543,"mutex_wait_us":1,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":4736,"update_count":2500}
I20260812 06:19:42.508873  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:42.538992  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.030s	user 0.017s	sys 0.011s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":13212,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:42.539444  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:42.554092  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.014s	user 0.011s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5303,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.554519  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushMRSOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:42.584052  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushMRSOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.029s	user 0.028s	sys 0.000s Metrics: {"bytes_written":1234479,"cfile_init":1,"dirs.queue_time_us":57,"dirs.run_cpu_time_us":213,"dirs.run_wall_time_us":1277,"drs_written":1,"lbm_read_time_us":37,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1371,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":30}
I20260812 06:19:42.585052  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling LogGCOp(84297449a5724d738740e0bbf2415db4): free 132118257 bytes of WAL
I20260812 06:19:42.585318  7670 log_reader.cc:385] T 84297449a5724d738740e0bbf2415db4: removed 13 log segments from log reader
I20260812 06:19:42.585369  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000014 (ops 67-71)
I20260812 06:19:42.585409  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000015 (ops 72-76)
I20260812 06:19:42.585467  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000016 (ops 77-81)
I20260812 06:19:42.585505  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000017 (ops 82-86)
I20260812 06:19:42.585529  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000018 (ops 87-90)
I20260812 06:19:42.585583  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000019 (ops 91-95)
I20260812 06:19:42.585649  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000020 (ops 96-100)
I20260812 06:19:42.585744  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000021 (ops 101-104)
I20260812 06:19:42.585819  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000022 (ops 105-109)
I20260812 06:19:42.585927  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000023 (ops 110-114)
I20260812 06:19:42.586033  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000024 (ops 115-119)
I20260812 06:19:42.586093  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000025 (ops 120-124)
I20260812 06:19:42.586128  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000026 (ops 125-128)
I20260812 06:19:42.608992  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: LogGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.024s	user 0.002s	sys 0.019s Metrics: {}
I20260812 06:19:42.609524  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=6.157687
I20260812 06:19:42.628510  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.019s	user 0.012s	sys 0.004s Metrics: {"bytes_written":7384594,"delete_count":0,"lbm_write_time_us":7484,"lbm_writes_lt_1ms":183,"reinsert_count":0,"update_count":900}
I20260812 06:19:42.629082  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4): 472 bytes on disk
I20260812 06:19:42.629565  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":72,"lbm_reads_lt_1ms":4}
I20260812 06:19:42.630167  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:42.787905  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.158s	user 0.109s	sys 0.048s Metrics: {"cfile_cache_miss":613,"cfile_cache_miss_bytes":28097732,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":3,"delta_iterators_relevant":3,"dirs.queue_time_us":172,"lbm_read_time_us":10126,"lbm_reads_lt_1ms":649,"lbm_write_time_us":31301,"lbm_writes_lt_1ms":623,"mutex_wait_us":20,"peak_mem_usage":72641004,"reinsert_count":0,"spinlock_wait_cycles":10496,"thread_start_us":74,"threads_started":1,"update_count":2900}
I20260812 06:19:42.788440  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=15.087375
I20260812 06:19:42.831037  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.042s	user 0.023s	sys 0.016s Metrics: {"bytes_written":17230394,"delete_count":0,"lbm_write_time_us":17808,"lbm_writes_lt_1ms":423,"reinsert_count":0,"update_count":2100}
I20260812 06:19:42.831570  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:42.845176  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.013s	user 0.003s	sys 0.008s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5071,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:42.845690  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.004827  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.159s	user 0.102s	sys 0.045s Metrics: {"cfile_cache_miss":552,"cfile_cache_miss_bytes":25636176,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":721,"lbm_read_time_us":9882,"lbm_reads_lt_1ms":592,"lbm_write_time_us":27141,"lbm_writes_lt_1ms":563,"mutex_wait_us":68,"peak_mem_usage":64976984,"reinsert_count":0,"spinlock_wait_cycles":9344,"update_count":2600}
I20260812 06:19:43.005300  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:43.054646  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.049s	user 0.025s	sys 0.023s Metrics: {"bytes_written":16409902,"delete_count":0,"lbm_write_time_us":24445,"lbm_writes_1-10_ms":2,"lbm_writes_lt_1ms":401,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.055193  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.068198  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.013s	user 0.002s	sys 0.009s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":4651,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.069033  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.211138  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.142s	user 0.118s	sys 0.020s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815684,"cfile_init":8,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":256,"lbm_read_time_us":9614,"lbm_reads_lt_1ms":564,"lbm_write_time_us":28325,"lbm_writes_lt_1ms":543,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":1408,"update_count":2500}
I20260812 06:19:43.211711  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=11.118625
I20260812 06:19:43.241277  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.029s	user 0.006s	sys 0.020s Metrics: {"bytes_written":12717735,"delete_count":0,"lbm_write_time_us":12618,"lbm_writes_lt_1ms":313,"reinsert_count":0,"update_count":1550}
I20260812 06:19:43.241775  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.252962  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.011s	user 0.005s	sys 0.005s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":4149,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.253424  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.374270  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.121s	user 0.093s	sys 0.027s 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":42,"lbm_read_time_us":6955,"lbm_reads_lt_1ms":464,"lbm_write_time_us":23776,"lbm_writes_lt_1ms":443,"mutex_wait_us":76,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":2304,"update_count":2000}
I20260812 06:19:43.374917  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:43.420239  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.045s	user 0.024s	sys 0.009s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":15058,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.420771  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.435683  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.015s	user 0.009s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":5602,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.436199  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.558830  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.122s	user 0.103s	sys 0.020s 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":245,"lbm_read_time_us":10346,"lbm_reads_lt_1ms":472,"lbm_write_time_us":22811,"lbm_writes_lt_1ms":443,"mutex_wait_us":22,"peak_mem_usage":50689328,"reinsert_count":0,"spinlock_wait_cycles":7936,"update_count":2000}
I20260812 06:19:43.559269  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:43.609009  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.050s	user 0.020s	sys 0.019s Metrics: {"bytes_written":12307490,"delete_count":0,"lbm_write_time_us":14903,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.609500  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.619343  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3861,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.619772  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.762058  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.142s	user 0.102s	sys 0.037s 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":1435,"lbm_read_time_us":10103,"lbm_reads_lt_1ms":472,"lbm_write_time_us":23152,"lbm_writes_lt_1ms":443,"mutex_wait_us":1114,"peak_mem_usage":50689328,"reinsert_count":0,"update_count":2000}
I20260812 06:19:43.763481  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=10.126437
I20260812 06:19:43.809770  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.046s	user 0.034s	sys 0.001s Metrics: {"bytes_written":12307492,"delete_count":0,"lbm_write_time_us":16535,"lbm_writes_lt_1ms":303,"reinsert_count":0,"update_count":1500}
I20260812 06:19:43.810257  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.820128  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.004s	sys 0.005s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3838,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:43.820677  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushMRSOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:43.847813  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushMRSOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.027s	user 0.025s	sys 0.000s Metrics: {"bytes_written":1152510,"cfile_init":1,"dirs.queue_time_us":55,"dirs.run_cpu_time_us":203,"dirs.run_wall_time_us":1242,"drs_written":1,"lbm_read_time_us":52,"lbm_reads_lt_1ms":4,"lbm_write_time_us":1466,"lbm_writes_lt_1ms":39,"peak_mem_usage":0,"rows_written":28}
I20260812 06:19:43.848551  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling LogGCOp(84297449a5724d738740e0bbf2415db4): free 112239560 bytes of WAL
I20260812 06:19:43.848781  7670 log_reader.cc:385] T 84297449a5724d738740e0bbf2415db4: removed 11 log segments from log reader
I20260812 06:19:43.848839  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000027 (ops 129-133)
I20260812 06:19:43.848881  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000028 (ops 134-138)
I20260812 06:19:43.848924  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000029 (ops 139-142)
I20260812 06:19:43.848948  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000030 (ops 143-147)
I20260812 06:19:43.848968  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000031 (ops 148-152)
I20260812 06:19:43.848996  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000032 (ops 153-157)
I20260812 06:19:43.849030  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000033 (ops 158-162)
I20260812 06:19:43.849057  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000034 (ops 163-167)
I20260812 06:19:43.849085  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000035 (ops 168-172)
I20260812 06:19:43.849112  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000036 (ops 173-177)
I20260812 06:19:43.849141  7670 log.cc:1079] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: Deleting log segment in path: /tmp/dist-test-taskFhgx5j/test-tmp/heavy-update-compaction-itest.0.EvictionPolicyTypes_HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction_1.1786515574301604-7148-0/minicluster-data/ts-0-root/wals/84297449a5724d738740e0bbf2415db4/wal-000000037 (ops 178-182)
I20260812 06:19:43.873445  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: LogGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.025s	user 0.000s	sys 0.021s Metrics: {}
I20260812 06:19:43.873932  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4): 448 bytes on disk
I20260812 06:19:43.874390  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: UndoDeltaBlockGCOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.000s	user 0.000s	sys 0.000s Metrics: {"cfile_init":1,"lbm_read_time_us":66,"lbm_reads_lt_1ms":4}
I20260812 06:19:43.875059  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=3.181125
I20260812 06:19:43.894105  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.019s	user 0.009s	sys 0.008s Metrics: {"bytes_written":4512899,"delete_count":0,"lbm_write_time_us":6827,"lbm_writes_lt_1ms":113,"reinsert_count":0,"update_count":550}
I20260812 06:19:43.894521  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:43.910409  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.016s	user 0.008s	sys 0.007s Metrics: {"bytes_written":3692405,"delete_count":0,"lbm_write_time_us":3256,"lbm_writes_lt_1ms":93,"reinsert_count":0,"update_count":450}
I20260812 06:19:43.910908  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:44.112717  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.202s	user 0.117s	sys 0.084s Metrics: {"cfile_cache_miss":634,"cfile_cache_miss_bytes":28918322,"cfile_init":10,"delete_count":0,"delta_blocks_compacted":4,"delta_iterators_relevant":4,"dirs.queue_time_us":369,"lbm_read_time_us":14234,"lbm_reads_lt_1ms":674,"lbm_write_time_us":34358,"lbm_writes_lt_1ms":643,"peak_mem_usage":75542472,"reinsert_count":0,"spinlock_wait_cycles":4864,"thread_start_us":80,"threads_started":1,"update_count":3000}
I20260812 06:19:44.113202  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=14.095187
I20260812 06:19:44.170629  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.057s	user 0.030s	sys 0.023s Metrics: {"bytes_written":16409901,"delete_count":0,"lbm_write_time_us":19299,"lbm_writes_lt_1ms":403,"reinsert_count":0,"spinlock_wait_cycles":1280,"update_count":2000}
I20260812 06:19:44.171154  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=2.188937
I20260812 06:19:44.181164  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.010s	user 0.004s	sys 0.004s Metrics: {"bytes_written":4102659,"delete_count":0,"lbm_write_time_us":3842,"lbm_writes_lt_1ms":103,"reinsert_count":0,"update_count":500}
I20260812 06:19:44.181615  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4): perf score=1.000000
I20260812 06:19:44.273702  7148 heavy-update-compaction-itest.cc:229] Time spent updating: real 4.605s	user 1.682s	sys 0.181s
I20260812 06:19:44.332576  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: MajorDeltaCompactionOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.151s	user 0.114s	sys 0.036s Metrics: {"cfile_cache_miss":532,"cfile_cache_miss_bytes":24815683,"cfile_init":9,"delete_count":0,"delta_blocks_compacted":2,"delta_iterators_relevant":2,"dirs.queue_time_us":1609,"lbm_read_time_us":11800,"lbm_reads_lt_1ms":568,"lbm_write_time_us":23740,"lbm_writes_lt_1ms":543,"mutex_wait_us":377,"peak_mem_usage":63115900,"reinsert_count":0,"spinlock_wait_cycles":2560,"update_count":2500}
I20260812 06:19:44.333098  7773 maintenance_manager.cc:419] P eeb4444707034bf6be626fd9e26e502f: Scheduling FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4): perf score=6.157687
I20260812 06:19:44.335098  7148 heavy-update-compaction-itest.cc:265] Time spent scanning: real 0.061s	user 0.002s	sys 0.000s
I20260812 06:19:44.335934  7148 tablet_server.cc:179] TabletServer@127.6.251.1:0 shutting down...
I20260812 06:19:44.353994  7670 maintenance_manager.cc:643] P eeb4444707034bf6be626fd9e26e502f: FlushDeltaMemStoresOp(84297449a5724d738740e0bbf2415db4) complete. Timing: real 0.021s	user 0.013s	sys 0.007s Metrics: {"bytes_written":8205078,"delete_count":0,"lbm_write_time_us":9022,"lbm_writes_lt_1ms":203,"reinsert_count":0,"update_count":1000}
I20260812 06:19:44.354535  7148 ts_tablet_manager.cc:1507] Shutting down tablet manager...
I20260812 06:19:44.354774  7148 tablet_replica.cc:333] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f: stopping tablet replica
I20260812 06:19:44.354890  7148 raft_consensus.cc:2243] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.355051  7148 raft_consensus.cc:2272] T 84297449a5724d738740e0bbf2415db4 P eeb4444707034bf6be626fd9e26e502f [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.358023  7148 tablet_server.cc:196] TabletServer@127.6.251.1:0 shutdown complete.
I20260812 06:19:44.377800  7148 master.cc:562] Master@127.6.251.62:44189 shutting down...
I20260812 06:19:44.381505  7148 raft_consensus.cc:2243] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 1 LEADER]: Raft consensus shutting down.
I20260812 06:19:44.381662  7148 raft_consensus.cc:2272] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3 [term 1 FOLLOWER]: Raft consensus is shut down!
I20260812 06:19:44.381711  7148 tablet_replica.cc:333] T 00000000000000000000000000000000 P e1f6d6df71b241dc8413a7c99eac7bd3: stopping tablet replica
I20260812 06:19:44.393798  7148 master.cc:584] Master@127.6.251.62:44189 shutdown complete.
[       OK ] EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy.TestHeavyUpdateCompaction/1 (5014 ms)
[----------] 2 tests from EvictionPolicyTypes/HeavyUpdateCompactionITestWithEvictionPolicy (10170 ms total)

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